Invalid syntax in docker-volume-vsphere.conf can cause high CPU.

[MattAtTTU]

With the latest release, I've discovered an issue with the documentation of the docker-volume-vsphere.conf file which can lead to high CPU usage on a Linux system.

The documentation gives the following example of the file:

{
    "Driver": "vsphere"
    "MaxLogAgeDays": 28,
    "MaxLogSizeMb": 100,
    "LogPath": "/var/log",
    "LogLevel": "info"
}

In the above example, there should be a coma after "vsphere". Since there is not, having this file present in /etc/ and starting docker will result in docker continually trying to load the plugin, which causes high CPU usage on the system. This can be verified by looking at the output of /var/log/messages. In that file, we see the following error continuously looping:

Apr 26 11:50:42 entswarmtemp dockerd: time="2017-04-26T11:50:42-05:00" level=info plugin=826014563c424a2f6e2cd7a22aca5002606857a8d26f0244ec142db93a5ab99e
Apr 26 11:50:42 entswarmtemp dockerd: time="2017-04-26T11:50:42-05:00" level=info msg="goroutine 1 [running]:" plugin=826014563c424a2f6e2cd7a22aca5002606857a8d26f0244ec142db93a5ab99e
Apr 26 11:50:42 entswarmtemp dockerd: time="2017-04-26T11:50:42-05:00" level=info msg="panic(0x754860, 0xc420240670)" plugin=826014563c424a2f6e2cd7a22aca5002606857a8d26f0244ec142db93a5ab99e
Apr 26 11:50:42 entswarmtemp dockerd: time="2017-04-26T11:50:42-05:00" level=info msg="\t/usr/local/go/src/runtime/panic.go:500 +0x1a1" plugin=826014563c424a2f6e2cd7a22aca5002606857a8d26f0244ec142db93a5ab99e
Apr 26 11:50:42 entswarmtemp dockerd: time="2017-04-26T11:50:42-05:00" level=info msg="main.logInit(0xc42015fc48, 0x0, 0xc420240590, 0x7ca7a0)" plugin=826014563c424a2f6e2cd7a22aca5002606857a8d26f0244ec142db93a5ab99e
Apr 26 11:50:42 entswarmtemp dockerd: time="2017-04-26T11:50:42-05:00" level=info msg="\t/go/src/github.com/vmware/docker-volume-vsphere/vmdk_plugin/main.go:73 +0x497" plugin=826014563c424a2f6e2cd7a22aca5002606857a8d26f0244ec142db93a5ab99e
Apr 26 11:50:42 entswarmtemp dockerd: time="2017-04-26T11:50:42-05:00" level=info msg="main.main()" plugin=826014563c424a2f6e2cd7a22aca5002606857a8d26f0244ec142db93a5ab99e
Apr 26 11:50:42 entswarmtemp dockerd: time="2017-04-26T11:50:42-05:00" level=info msg="\t/go/src/github.com/vmware/docker-volume-vsphere/vmdk_plugin/main.go:122 +0x2f0" plugin=826014563c424a2f6e2cd7a22aca5002606857a8d26f0244ec142db93a5ab99e
Apr 26 11:50:42 entswarmtemp dockerd: time="2017-04-26T11:50:42-05:00" level=info msg="panic: Failed to load config file /etc/docker-volume-vsphere.conf: invalid character '\"' after object key:value pair" plugin=826014563c424a2f6e2cd7a22aca

Additionally, there is one more discrepancy in the documentation which doesn't cause the CPU issue but will result in logging trouble. It seems the fully qualified path to the log file must be specified. The example in the documentation shows only "/var/log" as the example. If that is used, messages can be observed in /var/log/messages indicating /var/log is unavailable. If a fully qualified file path such as "/var/log/docker-volume-vsphere.log" is used, the log file will be written to as expected.

[pdhamdhere]

Argh :( That's an excellent catch, Matt and thanks for detective work in nailing down high CPU utilization to documentation.

@shuklanirdesh82 Can you please sanity test config file options and push doc fix.

[shuklanirdesh82]

#1194 (comment)
Can you please sanity test config file options and push doc fix.

Sure thing!

[shuklanirdesh82]

@pdhamdhere's comment: #1194 (comment)
Can you please sanity test config file options and push doc fix.

Testing done: As a quick sanity following steps were followed.

1. reproduce the issue locally > line "LogPath": "/var/log, created a new file and moved previous logs to dated folder
2. cleaned up everything locally
3. corrected /etc/docker-volume-vsphere.conf for driver (supplying an extra ,) and LogPath
4. restart docker-volume-vsphere to refresh the log changes
5. create volume > rm volume > verifies logs at the location mentioned at LogPath

Additional testing has been done for Driver (by changing vsphere => vmdk (legacy driver) and back to vsphere and make sure log output verifies the activity.

Affected changes are checked in and document is refreshed see here

[shuklanirdesh82]

@MattAtTTU,

Sorry for the inconvenience, changed are merged and document site is refreshed. Please reach us out if you have any other concern.

Thanks for reporting this issue!