Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Log output of commands to logfile #520

Merged
merged 1 commit into from
Jun 14, 2019
Merged

Conversation

vojtechsokol
Copy link
Member

No description provided.

@centos-ci
Copy link

Can one of the admins verify this patch?

@vojtechsokol vojtechsokol force-pushed the log_output branch 2 times, most recently from 22cfb26 to 821c49b Compare June 5, 2019 15:45
@vojtechsokol vojtechsokol requested a review from a team June 5, 2019 21:05
@jmikovic
Copy link
Contributor

Output of commands is mixing with logging info in the file which makes it difficult to read.

example:

2019-06-10 08:57:33.763 DEBUG    PID: 17232 leapp.workflow.FactsCollection.pci_devices_scanner: External command is started: [lspci -mm]
2019-06-10 08:57:33.837 DEBUG    PID: 17232 leapp.workflow.FactsCollection.pci_devices_scanner: 00:00.0 "Host bridge" "Intel Corporation" "440FX - 82441FX PMC [Natoma]" -r02 "R
2019-06-10 08:57:33.849 DEBUG    PID: 17232 leapp.workflow.FactsCollection.pci_devices_scanner: ed Hat, Inc." "Qemu virtual machine"
00:01.0 "ISA bridge" "Intel Corporation" "8
2019-06-10 08:57:33.857 DEBUG    PID: 17232 leapp.workflow.FactsCollection.pci_devices_scanner: 2371SB PIIX3 ISA [Natoma/Triton II]" "Red Hat, Inc." "Qemu virtual machine"
00:0
2019-06-10 08:57:33.865 DEBUG    PID: 17232 leapp.workflow.FactsCollection.pci_devices_scanner: 1.1 "IDE interface" "Intel Corporation" "82371SB PIIX3 IDE [Natoma/Triton II]" -
2019-06-10 08:57:33.873 DEBUG    PID: 17232 leapp.workflow.FactsCollection.pci_devices_scanner: p80 "Red Hat, Inc." "Qemu virtual machine"
00:01.2 "USB controller" "Intel Corpo
2019-06-10 08:57:33.882 DEBUG    PID: 17232 leapp.workflow.FactsCollection.pci_devices_scanner: ration" "82371SB PIIX3 USB [Natoma/Triton II]" -r01 "Red Hat, Inc." "QEMU Virtua
2019-06-10 08:57:33.896 DEBUG    PID: 17232 leapp.workflow.FactsCollection.pci_devices_scanner: l Machine"
00:01.3 "Bridge" "Intel Corporation" "82371AB/EB/MB PIIX4 ACPI" -r03 
2019-06-10 08:57:33.905 DEBUG    PID: 17232 leapp.workflow.FactsCollection.pci_devices_scanner: "Red Hat, Inc." "Qemu virtual machine"
00:02.0 "SCSI storage controller" "Red Ha
2019-06-10 08:57:33.915 DEBUG    PID: 17232 leapp.workflow.FactsCollection.pci_devices_scanner: t, Inc." "Virtio block device" "Red Hat, Inc." "Device 0002"
00:03.0 "Unclassifi
2019-06-10 08:57:33.923 DEBUG    PID: 17232 leapp.workflow.FactsCollection.pci_devices_scanner: ed device [00ff]" "Red Hat, Inc." "Virtio memory balloon" "Red Hat, Inc." "Devic
2019-06-10 08:57:33.931 DEBUG    PID: 17232 leapp.workflow.FactsCollection.pci_devices_scanner: e 0005"
00:04.0 "Ethernet controller" "Red Hat, Inc." "Virtio network device" "R
2019-06-10 08:57:33.943 DEBUG    PID: 17232 leapp.workflow.FactsCollection.pci_devices_scanner: ed Hat, Inc." "Device 0001"

2019-06-10 08:57:33.975 DEBUG    PID: 17232 leapp.workflow.FactsCollection.pci_devices_scanner: External command is finished: [lspci -mm]

@vojtechsokol
Copy link
Member Author

@jmikovic That is a problem with the way how the output of external command is handled in _call function. It is read in chunks of 80 bytes. If the output of the command doesn't fit into 80 bytes, it gets split and is printed to the log file in more lines. An also if the output of the command contains a newline, it gets printed to the log file including the newline, therefore the lines in the logfile without the logging prefix.

I'm not sure whether it's worth it to dig deep into the internals of the _call to correctly log the output to the file...

@vojtechsokol
Copy link
Member Author

Taking my last comment back, it looks like argument callback_linebuffered of function _call should do the trick.

@vojtechsokol
Copy link
Member Author

Messed up lines in logfile are now fixed.

However now I wonder whether it makes sense to use raw logging of commands' output to terminal when in debug mode. Because everything is logged to terminal with logging prefix, except for the output of external programs.

@jmikovic
Copy link
Contributor

it would be best if there isn't logging prefix for command output, it will make it much easier to read

@vojtechsokol
Copy link
Member Author

You mean even for the logfile? I don't think that's a good idea, every line in the logfile should have a logging prefix to be auditable.

@jmikovic
Copy link
Contributor

Yes, it's fine if the logging prefix is at the beginning of command output but having it on each line of output seems too much to me

@bocekm
Copy link
Member

bocekm commented Jun 11, 2019

I also think that having every line in the log file prefixed is not necessary. Right now, some actors log multiline strings and I see no problem with it, e.g.

2019-06-11 08:43:19.497 DEBUG    PID: 3619 leapp.workflow.FactsCollection.pes_events_scanner: The following packages will not be installed because of the /etc/leapp/transaction/to_remove transaction configuration file:
- perl-IPC-SysV
- perl-Devel-Peek
- perl-ExtUtils-Command

@vojtechsokol
Copy link
Member Author

I'm still not convinced that not having a logging prefix for each line is a good idea. When prefix is not included in every line, this could lead to a situation, when there are 2 loggers that write to a logfile at the same time, and you are not able to distinguish what line belongs to what process when the prefix is missing. @shaded-enmity @pirat89 what do you think?

@pirat89
Copy link
Member

pirat89 commented Jun 11, 2019

@vojtechsokol why it should be problem? The message is printed through our API - so there should not be any problem with logging. Additionally, there is not parrallel processing in that time. I am maybe missing something. (I have too many contexts now)

@bocekm
Copy link
Member

bocekm commented Jun 11, 2019

I share @pirat89's sentiment. I see no reason why the logfile entries should be intermixed. We have one logger handler for the logfile. Can you think of any scenario when we would need more than one logfile logging handler?

@vojtechsokol
Copy link
Member Author

Each actor has it's own handler, but as @pirat89 pointed out, there is no parallel processing of actors ATM, maybe I'm thinkig too much in the future. OK, I'll try to modify the logging so that only one logging prefix is used for the whole output of one executed command.

@jmikovic jmikovic merged commit cb60658 into oamg:master Jun 14, 2019
@vojtechsokol vojtechsokol deleted the log_output branch June 14, 2019 13:10
pirat89 added a commit to pirat89/leapp that referenced this pull request Jul 15, 2019
Packaging
- Fix URL and Source0 in the SPEC file

=====================================================================
Framework
* Fixes
- Add workround patch for the multiprocessing library
- Exit non-zero on unhandled exceptions and errors
- Fix actor library loading, so libs do not have to be imported
  in lexicographical order
- Fix buf with mode inheritance and list field (oamg#203)
- Fix warning about membership check of models when (oamg#503)
- Load checkpoint ordered by `id` instead of timestamp to prevent
  issues with changed timezone (oamg#499)
- Log on the ERROR level by default instead of DEBUG
- Print usage to stderr

* Enhancements
- Add phase name checking to workflow parameters
- Add the fetch_upgrade_report_raw() function to obtain raw report
  data
- Create a dynamic configuration phase that allows creation
  of configuration for repository workflow
- Functionalite getting actor and phase names when working with
  a workflow

=====================================================================
Leapp
* Fixes
- Add checks of arguments for cmdline parameters
- Load checkpoint ordered by `id` instead of timestamp to prevent
  issues with changed timezone (oamg#499)

* Enhancements
- Add JSON report generation
- Add the preupgrade subcommand for the leapp tool that stops
  workflow execution after the Reports phase and display info about
  generated report

=====================================================================
Snactor
* Fixes
- Add a simple logger to snactor discover command to avoid spurious
  output about missing logger
- Add checks of arguments for cmdline parameters
- Exit non-zero on unhandled exceptions and errors
- Load checkpoint ordered by `id` instead of timestamp to prevent
  issues with changed timezone (oamg#499)

=====================================================================
stdlib
* Fixes
- Add checks of arguments for cmdline parameters

* Enhancements
- Log output of commands to logfile (oamg#520)
- stdlib: add option to `run()` to ignore exit code

=====================================================================
Modifications
- introduced conftest.py to utilize fixture mechanism, so fixture
  doesn't have to be imported explicitly in tests.
- refactoring to satisfy linters
@pirat89 pirat89 mentioned this pull request Jul 15, 2019
pirat89 added a commit that referenced this pull request Jul 15, 2019
Packaging
- Fix URL and Source0 in the SPEC file

=====================================================================
Framework
* Fixes
- Add workround patch for the multiprocessing library
- Exit non-zero on unhandled exceptions and errors
- Fix actor library loading, so libs do not have to be imported
  in lexicographical order
- Fix buf with mode inheritance and list field (#203)
- Fix warning about membership check of models when (#503)
- Load checkpoint ordered by `id` instead of timestamp to prevent
  issues with changed timezone (#499)
- Log on the ERROR level by default instead of DEBUG
- Print usage to stderr

* Enhancements
- Add phase name checking to workflow parameters
- Add the fetch_upgrade_report_raw() function to obtain raw report
  data
- Create a dynamic configuration phase that allows creation
  of configuration for repository workflow
- Functionalite getting actor and phase names when working with
  a workflow

=====================================================================
Leapp
* Fixes
- Add checks of arguments for cmdline parameters
- Load checkpoint ordered by `id` instead of timestamp to prevent
  issues with changed timezone (#499)

* Enhancements
- Add JSON report generation
- Add the preupgrade subcommand for the leapp tool that stops
  workflow execution after the Reports phase and display info about
  generated report

=====================================================================
Snactor
* Fixes
- Add a simple logger to snactor discover command to avoid spurious
  output about missing logger
- Add checks of arguments for cmdline parameters
- Exit non-zero on unhandled exceptions and errors
- Load checkpoint ordered by `id` instead of timestamp to prevent
  issues with changed timezone (#499)

=====================================================================
stdlib
* Fixes
- Add checks of arguments for cmdline parameters

* Enhancements
- Log output of commands to logfile (#520)
- stdlib: add option to `run()` to ignore exit code

=====================================================================
Modifications
- introduced conftest.py to utilize fixture mechanism, so fixture
  doesn't have to be imported explicitly in tests.
- refactoring to satisfy linters
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants