Skip to content
This repository has been archived by the owner on Jan 7, 2020. It is now read-only.

race condition in the logger package #621

Closed
suhussai opened this issue Dec 28, 2016 · 1 comment
Closed

race condition in the logger package #621

suhussai opened this issue Dec 28, 2016 · 1 comment
Milestone
0.22.0

Comments

@suhussai
Copy link
Contributor

Expected Behavior

No race conditions upon startup.

Current Behavior

Currently, the Go race detector reports several race conditions when running uchiwa. They are shown below:

$ ./build/uchiwa
{"timestamp":"2016-12-28T15:59:29.12555259-07:00","level":"warn","message":"Loading the configuration file ./config.json"}
{"timestamp":"2016-12-28T15:59:29.127139264-07:00","level":"info","message":"Updating the datacenter Site 1"}
==================
WARNING: DATA RACE
Write at 0x00c420016210 by main goroutine:
  github.com/sensu/uchiwa/uchiwa/logger.(*Logger).now()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:67 +0x68
  github.com/sensu/uchiwa/uchiwa/logger.(*Logger).print()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:71 +0x8f
  github.com/sensu/uchiwa/uchiwa/logger.Warningf()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:152 +0xdf
  github.com/sensu/uchiwa/uchiwa.(*Uchiwa).WebServer()
      /src/github.com/sensu/uchiwa/uchiwa/server.go:1122 +0x1726
  main.main()
      /src/github.com/sensu/uchiwa/uchiwa.go:40 +0x44f

Previous write at 0x00c420016210 by goroutine 6:
  github.com/sensu/uchiwa/uchiwa/logger.(*Logger).now()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:67 +0x68
  github.com/sensu/uchiwa/uchiwa/logger.(*Logger).print()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:71 +0x8f
  github.com/sensu/uchiwa/uchiwa/logger.Infof()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:128 +0xdf
  github.com/sensu/uchiwa/uchiwa/daemon.(*Daemon).fetchData()
      /src/github.com/sensu/uchiwa/uchiwa/daemon/daemon.go:74 +0x30b
  github.com/sensu/uchiwa/uchiwa/daemon.(*Daemon).Start()
      /src/github.com/sensu/uchiwa/uchiwa/daemon/daemon.go:29 +0x6a

Goroutine 6 (running) created at:
  github.com/sensu/uchiwa/uchiwa.Init()
      /src/github.com/sensu/uchiwa/uchiwa/main.go:48 +0x3e3
  main.main()
      /src/github.com/sensu/uchiwa/uchiwa.go:22 +0x190
==================
==================
WARNING: DATA RACE
Write at 0x00c420016218 by main goroutine:
  github.com/sensu/uchiwa/uchiwa/logger.(*Logger).now()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:67 +0x68
  github.com/sensu/uchiwa/uchiwa/logger.(*Logger).print()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:71 +0x8f
  github.com/sensu/uchiwa/uchiwa/logger.Warningf()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:152 +0xdf
  github.com/sensu/uchiwa/uchiwa.(*Uchiwa).WebServer()
      /src/github.com/sensu/uchiwa/uchiwa/server.go:1122 +0x1726
  main.main()
      /src/github.com/sensu/uchiwa/uchiwa.go:40 +0x44f

Previous write at 0x00c420016218 by goroutine 6:
  github.com/sensu/uchiwa/uchiwa/logger.(*Logger).now()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:67 +0x68
  github.com/sensu/uchiwa/uchiwa/logger.(*Logger).print()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:71 +0x8f
  github.com/sensu/uchiwa/uchiwa/logger.Debugf()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:102 +0xdf
  github.com/sensu/uchiwa/uchiwa/sensu.(*Sensu).getSlice()
      /src/github.com/sensu/uchiwa/uchiwa/sensu/loadbalancing.go:50 +0x276
  github.com/sensu/uchiwa/uchiwa/sensu.(*Sensu).GetStashes()
      /src/github.com/sensu/uchiwa/uchiwa/sensu/stashes.go:10 +0x90
  github.com/sensu/uchiwa/uchiwa/daemon.(*Daemon).fetchData()
      /src/github.com/sensu/uchiwa/uchiwa/daemon/daemon.go:81 +0x418
  github.com/sensu/uchiwa/uchiwa/daemon.(*Daemon).Start()
      /src/github.com/sensu/uchiwa/uchiwa/daemon/daemon.go:29 +0x6a

Goroutine 6 (running) created at:
  github.com/sensu/uchiwa/uchiwa.Init()
      /src/github.com/sensu/uchiwa/uchiwa/main.go:48 +0x3e3
  main.main()
      /src/github.com/sensu/uchiwa/uchiwa.go:22 +0x190
==================
==================
WARNING: DATA RACE
Write at 0x00c420016238 by main goroutine:
  github.com/sensu/uchiwa/uchiwa/logger.(*Logger).print()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:72 +0x108
  github.com/sensu/uchiwa/uchiwa/logger.Warningf()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:152 +0xdf
  github.com/sensu/uchiwa/uchiwa.(*Uchiwa).WebServer()
      /src/github.com/sensu/uchiwa/uchiwa/server.go:1122 +0x1726
  main.main()
      /src/github.com/sensu/uchiwa/uchiwa.go:40 +0x44f

Previous write at 0x00c420016238 by goroutine 6:
  github.com/sensu/uchiwa/uchiwa/logger.(*Logger).print()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:72 +0x108
  github.com/sensu/uchiwa/uchiwa/logger.Debugf()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:102 +0xdf
  github.com/sensu/uchiwa/uchiwa/sensu.(*Sensu).getSlice()
      /src/github.com/sensu/uchiwa/uchiwa/sensu/loadbalancing.go:50 +0x276
  github.com/sensu/uchiwa/uchiwa/sensu.(*Sensu).GetStashes()
      /src/github.com/sensu/uchiwa/uchiwa/sensu/stashes.go:10 +0x90
  github.com/sensu/uchiwa/uchiwa/daemon.(*Daemon).fetchData()
      /src/github.com/sensu/uchiwa/uchiwa/daemon/daemon.go:81 +0x418
  github.com/sensu/uchiwa/uchiwa/daemon.(*Daemon).Start()
      /src/github.com/sensu/uchiwa/uchiwa/daemon/daemon.go:29 +0x6a

Goroutine 6 (running) created at:
  github.com/sensu/uchiwa/uchiwa.Init()
      /src/github.com/sensu/uchiwa/uchiwa/main.go:48 +0x3e3
  main.main()
      /src/github.com/sensu/uchiwa/uchiwa.go:22 +0x190
==================
==================
WARNING: DATA RACE
Write at 0x00c420016228 by main goroutine:
  github.com/sensu/uchiwa/uchiwa/logger.(*Logger).print()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:73 +0x13e
  github.com/sensu/uchiwa/uchiwa/logger.Warningf()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:152 +0xdf
  github.com/sensu/uchiwa/uchiwa.(*Uchiwa).WebServer()
      /src/github.com/sensu/uchiwa/uchiwa/server.go:1122 +0x1726
  main.main()
      /src/github.com/sensu/uchiwa/uchiwa.go:40 +0x44f

Previous write at 0x00c420016228 by goroutine 6:
  github.com/sensu/uchiwa/uchiwa/logger.(*Logger).print()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:73 +0x13e
  github.com/sensu/uchiwa/uchiwa/logger.Debugf()
      /src/github.com/sensu/uchiwa/uchiwa/logger/logger.go:102 +0xdf
  github.com/sensu/uchiwa/uchiwa/sensu.(*Sensu).getSlice()
      /src/github.com/sensu/uchiwa/uchiwa/sensu/loadbalancing.go:50 +0x276
  github.com/sensu/uchiwa/uchiwa/sensu.(*Sensu).GetStashes()
      /src/github.com/sensu/uchiwa/uchiwa/sensu/stashes.go:10 +0x90
  github.com/sensu/uchiwa/uchiwa/daemon.(*Daemon).fetchData()
      /src/github.com/sensu/uchiwa/uchiwa/daemon/daemon.go:81 +0x418
  github.com/sensu/uchiwa/uchiwa/daemon.(*Daemon).Start()
      /src/github.com/sensu/uchiwa/uchiwa/daemon/daemon.go:29 +0x6a

Goroutine 6 (running) created at:
  github.com/sensu/uchiwa/uchiwa.Init()
      /src/github.com/sensu/uchiwa/uchiwa/main.go:48 +0x3e3
  main.main()
      /src/github.com/sensu/uchiwa/uchiwa.go:22 +0x190
==================
{"timestamp":"2016-12-28T15:59:29.127384026-07:00","level":"warn","message":"Uchiwa is now listening on 0.0.0.0:3000"}

Possible Solution

A simple mutex surrounding the resource that needs to be shared properly can fix the issue. Another solution might be to setup a Go routine that uses select to block on a channel as part of the logger package initialization. This Go routine could then direct any incoming messages to the print function in the logger package.

Steps to Reproduce (for bugs)

  1. Pull a fresh copy of the repo.
  2. Build the package with the race flag like so: $ go build -race -o build/uchiwa .
  3. Run Uchiwa: $ ./build/uchiwa

Context

We were seeing issues where Uchiwa would randomly crash so I decided to use the Go race detector to see what I could find. Although it is unlikely that this was the issue that we were seeing, I think that by creating a safe way to log messages may help reduce resource contention.

Your Environment

  • Uchiwa version used: 0.21.0
  • Sensu version used: Not Relevant
  • Operating System and version (e.g. Ubuntu 14.04): OSX El Capitan 10.11.06
@suhussai suhussai mentioned this issue Dec 28, 2016
Merged
8 tasks
@palourde
Copy link
Contributor

palourde commented Jan 6, 2017

Fixed by #622

@palourde palourde closed this as completed Jan 6, 2017
@palourde palourde added this to the 0.22.0 milestone Jan 6, 2017
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
0.22.0
Development

No branches or pull requests
2 participants
@palourde @suhussai