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

We need configuration logging at info by default. #453

Open
MatthewHink opened this issue Feb 26, 2020 · 11 comments
Open

We need configuration logging at info by default. #453

MatthewHink opened this issue Feb 26, 2020 · 11 comments
Assignees
@MatthewHink
Labels
bug synse v3

Comments

@MatthewHink
Copy link
Contributor

I see debug level log statements, but the configuration is not in the log.
We need the configuration in the log for bug reports since the configuration is complex and the pod may no longer be available.

I had put this in in the past here:
https://github.com/vapor-ware/synse-sdk/pull/115/files

log-snippet.txt
@MatthewHink
Copy link
Contributor Author

So I'm wrong. Part of the device configuration is logged at debug. We need it all logged at info.

time="2020-02-26T21:53:02.348Z" level=debug msg="[device manager] applied filter to devices" action="log device configurations" filter="map[type:[*]]" matches=24
time="2020-02-26T21:53:02.348Z" level=debug msg="[i2c] logging device configuration" data="map[channel:A4/A3/A2 chip:U1 control_port:A4 els_port:A3 mls_port:A2]" id=f42cf57d-6b90-5f55-b535-f53f5b7e8b43 type=lock
time="2020-02-26T21:53:02.348Z" level=debug msg="[i2c] logging device configuration" data="map[channel:B4/B5/B6 chip:U1 control_port:B4 els_port:B5 mls_port:B6]" id=c7948ef7-3632-5c3a-bc58-79e267c7a1cb type=lock
time="2020-02-26T21:53:02.348Z" level=debug msg="[i2c] logging device configuration" data="map[channel:A6/A7/B6 chip:U2 control_port:A6 els_port:A7 mls_port:B6]" id=edd1db2e-e8af-5d49-922f-bf4a55147873 type=lock
time="2020-02-26T21:53:02.348Z" level=debug msg="[i2c] logging device configuration" data="map[channel:0002]" id=db3a533a-c60a-5ff8-830b-29505f217388 type=pressure
time="2020-02-26T21:53:02.348Z" level=debug msg="[i2c] logging device configuration" data="map[channel:0002]" id=0e89d058-88de-5b68-a3df-a6a4f21a571d type=temperature
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:0006]" id=f4a1b043-2628-57cd-ab75-c93189961524 type=temperature
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:0008]" id=2150b47b-326d-5cc9-a6d8-cd2f76b55256 type=temperature
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:000b]" id=07808c21-d085-5957-abbb-eb658a46fe10 type=temperature
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:0001]" id=cedf3d4f-6d47-5c37-a08a-a0cc0fc663c8 type=pressure
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:0000]" id=d09e5ef5-9686-50b4-a0a3-485bda5e6d31 type=temperature
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:0009]" id=f7a0f79e-5cf2-5a9a-b865-18268c8ff4de type=temperature
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:000a]" id=dddec031-830c-5cf0-baba-c5f1201111e7 type=temperature
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:A3/A4/A5 chip:U2 control_port:A3 els_port:A4 mls_port:A5]" id=5f8e2880-8955-5396-8464-4b0529623ebd type=lock
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:B5/B4/B3 chip:U2 control_port:B5 els_port:B4 mls_port:B3]" id=71831f61-23d4-567e-ae78-2dd1801ca455 type=lock
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:0001]" id=f10885fc-84ae-5acf-854c-eb8a9750c876 type=temperature
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:0003]" id=0fb29caf-3cb7-5478-a2b5-b22e7ba7d71b type=temperature
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:0004]" id=8f75f6e6-d2c3-5d0e-98d7-6c33d9d5f642 type=temperature
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:0007]" id=233067af-f121-558d-a579-272dee1d30e1 type=temperature
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:A1/A0/B0 chip:U1 control_port:A1 els_port:A0 mls_port:B0]" id=b9f2263a-126d-5769-afb2-7ea79b99e5b4 type=lock
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:0004]" id=d1fced11-ea38-5426-bd60-222aa63bc8ab type=pressure
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:0005]" id=034673e9-f413-5167-a6f3-522557fa2009 type=temperature
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:A7/A6/A5 chip:U1 control_port:A7 els_port:A6 mls_port:A5]" id=c9b1fef5-6c4f-5cef-8b58-77195cc4e7d2 type=lock
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:B1/B2/B3 chip:U1 control_port:B1 els_port:B2 mls_port:B3]" id=01cfed9b-b5ee-5183-a625-ba8b6274d1c5 type=lock
time="2020-02-26T21:53:02.349Z" level=debug msg="[i2c] logging device configuration" data="map[channel:A0/A1/A2 chip:U2 control_port:A0 els_port:A1 mls_port:A2]" id=6d083416-b07b-5487-bd84-258709897f23 type=lock

@MatthewHink
Copy link
Contributor Author

Another thing to be clear on: We should log the file prior to loading any configuration. If we fail to load, the log may help us determine why.

@edaniszewski
Copy link
Contributor

when you say log the file, do you mean log the info about the file being loaded (e.g. directory, name) or the contents of the file? We already log the info about the file being loaded

time="2020-02-26T21:53:00.944Z" level=info msg="[config] loading configuration" ext=yaml loader=device name= paths="[./config/device /etc/synse/plugin/config/device]" policy=required
time="2020-02-26T21:53:00.944Z" level=debug msg="[config] loading ENV overrides"
time="2020-02-26T21:53:00.944Z" level=info msg="[config] ENV overrides loaded" file=config.yml paths="[/etc/synse/plugin/shared/]"
time="2020-02-26T21:53:00.944Z" level=info msg="[config] found matching config" file=config.yml loader=device path=/etc/synse/plugin/shared/ policy=required
time="2020-02-26T21:53:00.944Z" level=debug msg="[config] reading config file" file=/etc/synse/plugin/shared/config.yml
time="2020-02-26T21:53:00.945Z" level=debug msg="[config] merging configuration sources"

@edaniszewski
Copy link
Contributor

the device configuration logged at debug level originates in the i2c plugin, so the log level would need to be fixed there

@edaniszewski edaniszewski mentioned this issue Feb 28, 2020
Merged
@edaniszewski
Copy link
Contributor

I think with the PR referenced above, this should be okay to close. @MatthewHink feel free to close if you agree. If theres something here that was missed in the PR, let me know so I can add it.

@MatthewHink MatthewHink self-assigned this Mar 12, 2020
@MatthewHink
Copy link
Contributor Author

I'm going to add more logging here. It's hard to tell what is happening. We don't have the config file contents in the log and the container has died.

time="2020-03-12T17:22:49.363Z" level=debug msg="[config] reading config file" file=/etc/synse/plugin/config/device/config.yml
time="2020-03-12T17:22:49.364Z" level=error msg="[config] failed to unmarshal config data" error="yaml: unmarshal errors:\n line 1: cannot unmarshal !!seq into map[string]interface {}"
time="2020-03-12T17:22:49.364Z" level=error msg="[plugin] failed to initialize plugin"
time="2020-03-12T17:22:49.364Z" level=fatal msg="yaml: unmarshal errors:\n line 1: cannot unmarshal !!seq into map[string]interface {}"

@edaniszewski
Copy link
Contributor

I'm not sure that we want the config file contents in the logs.. If we do that, theres no way to redact any sensitive info which may be in the config.

@MatthewHink
Copy link
Contributor Author

Well then how do we debug this? How do we know the configuration when a bug report is filed?

@edaniszewski
Copy link
Contributor

I'm not sure what the best way is, it just seems to me like we don't want to be leaking potential passwords in logs. I'd prefer not to, but we could also just have it log out at a low log level and I guess add a disclaimer that debug/trace logs can leak passwords if they are in the config. Maybe thats okay, but it feels weird to me.

For bug reports, we could just leave it to the reporter to provide the config with the expectation that sensitive info is stripped out.

@MatthewHink
Copy link
Contributor Author

True we do not want to log passwords, but we had this in synse v2 and we had rudimentary redaction.

For bug reports, we could just leave it to the reporter to provide the config with the expectation that sensitive info is stripped out.

This is blaming the victim. Don't agree.

The question remains: How do we debug this?

@MatthewHink
Copy link
Contributor Author

MatthewHink commented Mar 13, 2020 •
edited

And how do you even know what the config is with all of the templating levels? (helm/helmfile) Please tell me.

And how do you get the config file contents when the container has crashed? ls is not on the images.

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

@MatthewHink MatthewHink

Labels
bug synse v3
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@edaniszewski @MatthewHink