Skip to content
This repository was archived by the owner on Feb 18, 2025. It is now read-only.

Update from openark/golib to support TZ with logging#1017

Merged
jfudally merged 13 commits intomasterfrom
jfudally-timezone-support
Dec 5, 2019
Merged

Update from openark/golib to support TZ with logging#1017
jfudally merged 13 commits intomasterfrom
jfudally-timezone-support

Conversation

@jfudally
Copy link
Contributor

@jfudally jfudally commented Nov 12, 2019 •
edited
Loading

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

@jfudally jfudally self-assigned this Nov 12, 2019
shlomi-noach
shlomi-noach suggested changes Nov 18, 2019
View reviewed changes
Copy link
Collaborator

@shlomi-noach shlomi-noach left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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
Copy link
Contributor Author

jfudally commented Nov 25, 2019

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

@shlomi-noach shlomi-noach had a problem deploying to production/mysql_cluster=concertmaster December 4, 2019 08:45 Failure
@shlomi-noach shlomi-noach had a problem deploying to production/mysql_cluster=concertmaster December 4, 2019 08:45 Failure
@shlomi-noach shlomi-noach temporarily deployed to production/mysql_cluster=concertmaster December 4, 2019 08:51 Inactive
@shlomi-noach
Copy link
Collaborator

shlomi-noach commented Dec 4, 2019

@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 jfudally temporarily deployed to production/mysql_cluster=concertmaster December 4, 2019 15:23 Inactive
@jfudally
Copy link
Contributor Author

jfudally commented Dec 4, 2019 •
edited
Loading

@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?

@jfudally jfudally had a problem deploying to production/mysql_cluster=concertmaster December 5, 2019 07:01 Failure
@jfudally jfudally temporarily deployed to production/mysql_cluster=concertmaster December 5, 2019 16:28 Inactive
shlomi-noach
shlomi-noach approved these changes Dec 5, 2019
View reviewed changes
Copy link
Collaborator

@shlomi-noach shlomi-noach left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

assuming testing works - please merge!

@jfudally
Copy link
Contributor Author

jfudally commented Dec 5, 2019

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: "")

@jfudally jfudally merged commit 855e930 into master Dec 5, 2019
@jfudally jfudally deleted the jfudally-timezone-support branch December 5, 2019 16:39
@jfudally jfudally deleted the jfudally-timezone-support branch December 5, 2019 16:39
@ihanick ihanick mentioned this pull request Apr 14, 2021
Open
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Reviewers

1 more reviewer

@shlomi-noach shlomi-noach shlomi-noach approved these changes

Reviewers whose approvals may not affect merge requirements

Assignees

@jfudally jfudally

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

It does not seem possible to log explicitly in UTC (if TZ is set differently)

2 participants

@jfudally @shlomi-noach