Update from openark/golib to support TZ with logging

[jfudally]

This PR allows setting the timezone via TZ environment variable for localizing logging timestamps:

# UTC time
export TZ="UTC"
# Madrid
export TZ="Europe/Madrid"
# Local timezone
export TZ="Local"

This PR also removes the inconsistent use of the standard log package in go/raft/file_snapshot.go in favor of the openark/golib/log package used by the rest of the application.

• contributed code is using same conventions as original code
• code is formatted via gofmt (please avoid goimports)
• code is built via ./build.sh
• code is tested via go test ./go/...

Closes #1004

[shlomi-noach]

Hey @jfudally! Please note https://github.com/github/orchestrator/blob/master/vendor/github.com/openark/golib/log/log.go exists, and so you'd like to merge your log.go changes into that file instead of creating a new log.go file in a different path.

[jfudally]

@shlomi-noach Ah my bad I missed a directory. Fixed now.

[shlomi-noach]

@jfudally in our testing cluster, before deploying this, our logs show:

2019-12-04 00:51:24 INFO Received SIGTERM. Shutting down orchestrator
2019-12-04 00:51:24 INFO auditType:shutdown instance::0 cluster: message:Triggered via SIGTERM

immediately after deploying:

2019-12-04 08:51:24 INFO starting orchestrator, version: 7842c22731ac8b6b739bc061e6db66b0029d52d2
2019-12-04 08:51:24 INFO Read config: /etc/orchestrator.conf.json

Notice the 8-hour jump from before/after. Before==PST, after==UTC. On our testing cluster:

$ echo $TZ

<empty>

should this happen?

[jfudally]

@shlomi-noach
No it shouldn't 🤦‍♂ . I hadn't run it yet on our testing cluster, but I did fix it. Looking at the following logs and commands post-deployment it seems to be working as expected now:

/var/log/messages:

2019-12-04T07:23:59-08:00 db-mysql-d5e64e5 auth:info sshd[46503]: Starting session: command for deploy from 172.16.24.47 port 51790
2019-12-04T07:23:59-08:00 db-mysql-d5e64e5 authpriv:notice sudo[46886]:   deploy : TTY=unknown ; PWD=/home/deploy ; USER=root ; COMMAND=/bin/systemctl restart orchestrator
2019-12-04T07:23:59-08:00 db-mysql-d5e64e5 daemon:info systemd[1]: Stopping "orchestrator: MySQL replication management and visualization"...
2019-12-04T07:23:59-08:00 db-mysql-d5e64e5 daemon:info systemd[1]: Stopped "orchestrator: MySQL replication management and visualization".
2019-12-04T07:23:59-08:00 db-mysql-d5e64e5 daemon:info systemd[1]: Started "orchestrator: MySQL replication management and visualization".

/data/orchestrator/current/bin/orchestrator http:

2019-12-04 07:34:36 DEBUG Connected to orchestrator backend: orchestrator_srv:?@tcp(127.0.0.1:3306)/orchestrator?timeout=1s
2019-12-04 07:34:36 DEBUG Orchestrator pool SetMaxOpenConns: 128
2019-12-04 07:34:36 DEBUG Initializing orchestrator

TZ=UTC /data/orchestrator/current/bin/orchestrator http:

2019-12-04 15:34:52 DEBUG Connected to orchestrator backend: orchestrator_srv:?@tcp(127.0.0.1:3306)/orchestrator?timeout=1s
2019-12-04 15:34:52 DEBUG Orchestrator pool SetMaxOpenConns: 128
2019-12-04 15:34:52 DEBUG Initializing orchestrator

TZ=America/Los_Angeles /data/orchestrator/current/bin/orchestrator http:

2019-12-04 07:38:22 DEBUG Connected to orchestrator backend: orchestrator_srv:?@tcp(127.0.0.1:3306)/orchestrator?timeout=1s
2019-12-04 07:38:22 DEBUG Orchestrator pool SetMaxOpenConns: 128
2019-12-04 07:38:22 DEBUG Initializing orchestrator

Also, what's the best way to run a snapshot to test the logging that I updated?

[shlomi-noach]

assuming testing works - please merge!

[jfudally]

Raft snapshot logging looks good:

019/12/05 08:29:29 [INFO] raft: Starting snapshot up to 16459922
2019-12-05 08:29:29 INFO snapshot: Creating new snapshot at /var/lib/orchestrator/snapshots/711803-16459922-1575563369883.tmp
2019-12-05 08:29:29 DEBUG raft snapshot data created
2019-12-05 08:29:29 INFO snapshot: reaping snapshot /var/lib/orchestrator/snapshots/711802-16455304-1575537726660
2019/12/05 08:29:29 [INFO] raft: Compacting logs from 16449457 to 16449682
2019/12/05 08:29:29 [INFO] raft: Snapshot to 16459922 complete

And the integrity of the snapshot is unaffected:

2019-12-05 08:37:28 DEBUG raft snapshot restore applied
2019/12/05 08:37:28 [INFO] raft: Restored from snapshot 711803-16459922-1575563369883
2019-12-05 08:37:28 INFO new raft created
2019-12-05 08:37:28 INFO continuous discovery: starting
2019/12/05 08:37:28 [INFO] raft: Node at x.x.x.x :10008 [Follower] entering Follower state (Leader: "")