Log command execution by default

[igorwwwwwwwwwwwwwwwwwwww]

We use go-crond for GitLab. One of the challenges we've run into is that it is very silent by default, and the verbose mode is potentially overly verbose.

It would be great to log more information by default about commands starting and finishing.

Sample runs on the example config with these changes in place.

Plaintext

./go-crond --allow-unprivileged examples/crontab --verbose

INFO[0000] starting go-crond version 21.5.0-4-ga2d26eb-dirty (a2d26eb; go1.18.1)
INFO[0000] {"ShowVersion":false,"ShowOnlyVersion":false,"ShowHelp":false,"Cron":{"DefaultUser":"root","IncludeCronD":null,"Auto":false,"RunParts":null,"RunParts1m":null,"RunParts15m":null,"RunPartsHourly":null,"RunPartsDaily":null,"RunPartsWeekly":null,"RunPartsMonthly":null,"AllowUnprivileged":true,"WorkDir":"/","EnableUserSwitching":false},"Log":{"Verbose":true,"Json":false},"Server":{"Bind":"","Metrics":false}}
WARN[0000] go-crond is NOT running as root, disabling user switching
INFO[0000] cronjob added                                 command="sleep 5 && id >> /tmp/test-1" spec="* * * * *" user=root
INFO[0000] cronjob added                                 command="sleep 5 && id >> /tmp/test-2" spec="* * * * *" user=root
INFO[0000] cronjob added                                 command="id >> /tmp/test-3" spec="@every 1m" user=guest
INFO[0000] cronjob added                                 command="env >> /tmp/test-4" spec="@every 1m" user=guest
INFO[0000] cronjob added                                 command="env >> /tmp/test-5" spec="@every 5s" user=guest
INFO[0000] start runner with 5 jobs
INFO[0004] executing                                     command="env >> /tmp/test-5" spec="@every 5s" user=guest
INFO[0004] finished                                      command="env >> /tmp/test-5" elapsed_s=0.009727615 exitCode=0 result=success spec="@every 5s" user=guest
INFO[0009] executing                                     command="env >> /tmp/test-5" spec="@every 5s" user=guest
INFO[0009] finished                                      command="env >> /tmp/test-5" elapsed_s=0.009852734 exitCode=0 result=success spec="@every 5s" user=guest
^CINFO[0010] got signal: interrupt
INFO[0010] stop runner
INFO[0010] terminated

JSON

{"level":"info","msg":"starting go-crond version 21.5.0-4-ga2d26eb-dirty (a2d26eb; go1.18.1) ","time":"2022-07-21T16:02:39+02:00"}
{"level":"info","msg":"{\"ShowVersion\":false,\"ShowOnlyVersion\":false,\"ShowHelp\":false,\"Cron\":{\"DefaultUser\":\"root\",\"IncludeCronD\":null,\"Auto\":false,\"RunParts\":null,\"RunParts1m\":null,\"RunParts15m\":null,\"RunPartsHourly\":null,\"RunPartsDaily\":null,\"RunPartsWeekly\":null,\"RunPartsMonthly\":null,\"AllowUnprivileged\":true,\"WorkDir\":\"/\",\"EnableUserSwitching\":false},\"Log\":{\"Verbose\":true,\"Json\":true},\"Server\":{\"Bind\":\"\",\"Metrics\":false}}","time":"2022-07-21T16:02:39+02:00"}
{"level":"warning","msg":"go-crond is NOT running as root, disabling user switching","time":"2022-07-21T16:02:39+02:00"}
{"command":"sleep 5 \u0026\u0026 id \u003e\u003e /tmp/test-1","level":"info","msg":"cronjob added","spec":"* * * * *","time":"2022-07-21T16:02:39+02:00","user":"root"}
{"command":"sleep 5 \u0026\u0026 id \u003e\u003e /tmp/test-2","level":"info","msg":"cronjob added","spec":"* * * * *","time":"2022-07-21T16:02:39+02:00","user":"root"}
{"command":"id \u003e\u003e /tmp/test-3","level":"info","msg":"cronjob added","spec":"@every 1m","time":"2022-07-21T16:02:39+02:00","user":"guest"}
{"command":"env \u003e\u003e /tmp/test-4","level":"info","msg":"cronjob added","spec":"@every 1m","time":"2022-07-21T16:02:39+02:00","user":"guest"}
{"command":"env \u003e\u003e /tmp/test-5","level":"info","msg":"cronjob added","spec":"@every 5s","time":"2022-07-21T16:02:39+02:00","user":"guest"}
{"level":"info","msg":"start runner with 5 jobs\n","time":"2022-07-21T16:02:39+02:00"}
{"command":"env \u003e\u003e /tmp/test-5","level":"info","msg":"executing","spec":"@every 5s","time":"2022-07-21T16:02:44+02:00","user":"guest"}
{"command":"env \u003e\u003e /tmp/test-5","elapsed_s":0.009944815,"exitCode":0,"level":"info","msg":"finished","result":"success","spec":"@every 5s","time":"2022-07-21T16:02:44+02:00","user":"guest"}
{"command":"env \u003e\u003e /tmp/test-5","level":"info","msg":"executing","spec":"@every 5s","time":"2022-07-21T16:02:49+02:00","user":"guest"}
{"command":"env \u003e\u003e /tmp/test-5","elapsed_s":0.010204081,"exitCode":0,"level":"info","msg":"finished","result":"success","spec":"@every 5s","time":"2022-07-21T16:02:49+02:00","user":"guest"}
{"level":"info","msg":"got signal: interrupt","time":"2022-07-21T16:02:49+02:00"}
{"level":"info","msg":"stop runner","time":"2022-07-21T16:02:49+02:00"}
{"level":"info","msg":"terminated","time":"2022-07-21T16:02:49+02:00"}

[iloveitaly]

This seems like a great change! What can we do to merge it in?