supervisord AssertionError: Assertion failed for start.sh: RUNNING not in STARTING

[stcheng]

On one switch during starting process, both docker bgp and docker teamd are not started successfully.

root@sonic:/var/log# docker logs bgp
/usr/lib/python2.7/dist-packages/supervisor/options.py:296: UserWarning: Supervisord is running as root and it is searching for its configuration file in default locations (including its current working directory); you probably want to specify a "-c" argument specifying an absolute path to a configuration file for improved security.
  'Supervisord is running as root and it is searching '
2017-06-27 10:23:48,055 CRIT Supervisor running as root (no user in config file)
2017-06-27 10:23:48,074 WARN Included extra file "/etc/supervisor/conf.d/supervisord.conf" during parsing
2017-06-27 10:23:48,375 INFO RPC interface 'supervisor' initialized
2017-06-27 10:23:48,419 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2017-06-27 10:23:48,437 INFO supervisord started with pid 1
2017-06-27 10:23:49,439 INFO spawned: 'start.sh' with pid 7
2017-06-27 10:23:50,453 INFO success: start.sh entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2017-06-27 10:12:34,408 INFO spawned: 'rsyslogd' with pid 20
2017-06-27 10:12:35,418 INFO success: rsyslogd entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2017-06-27 10:12:36,208 INFO spawned: 'fpmsyncd' with pid 48
2017-06-27 10:12:37,284 INFO success: fpmsyncd entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Traceback (most recent call last):
  File "/usr/bin/supervisord", line 9, in <module>
    load_entry_point('supervisor==3.0', 'console_scripts', 'supervisord')()
  File "/usr/lib/python2.7/dist-packages/supervisor/supervisord.py", line 360, in main
    go(options)
  File "/usr/lib/python2.7/dist-packages/supervisor/supervisord.py", line 370, in go
    d.main()
  File "/usr/lib/python2.7/dist-packages/supervisor/supervisord.py", line 83, in main
    self.run()
  File "/usr/lib/python2.7/dist-packages/supervisor/supervisord.py", line 100, in run
    self.runforever()
  File "/usr/lib/python2.7/dist-packages/supervisor/supervisord.py", line 254, in runforever
    self.reap()
  File "/usr/lib/python2.7/dist-packages/supervisor/supervisord.py", line 288, in reap
    process.finish(pid, sts)
  File "/usr/lib/python2.7/dist-packages/supervisor/process.py", line 455, in finish
    self._assertInState(ProcessStates.STARTING)
  File "/usr/lib/python2.7/dist-packages/supervisor/process.py", line 179, in _assertInState
    self.config.name, current_state, allowable_states))
AssertionError: Assertion failed for start.sh: RUNNING not in STARTING

root@sonic:/var/log# docker logs teamd
/usr/lib/python2.7/dist-packages/supervisor/options.py:296: UserWarning: Supervisord is running as root and it is searching for its configuration file in default locations (including its current working directory); you probably want to specify a "-c" argument specifying an absolute path to a configuration file for improved security.
  'Supervisord is running as root and it is searching '
2017-06-27 10:23:48,275 CRIT Supervisor running as root (no user in config file)
2017-06-27 10:23:48,276 WARN Included extra file "/etc/supervisor/conf.d/supervisord.conf" during parsing
2017-06-27 10:23:48,732 INFO RPC interface 'supervisor' initialized
2017-06-27 10:23:48,735 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2017-06-27 10:23:48,740 INFO supervisord started with pid 1
2017-06-27 10:23:49,752 INFO spawned: 'start.sh' with pid 8
2017-06-27 10:23:50,789 INFO success: start.sh entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2017-06-27 10:12:37,278 INFO spawned: 'rsyslogd' with pid 28
2017-06-27 10:12:38,280 INFO success: rsyslogd entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2017-06-27 10:12:38,451 INFO spawned: 'teamd' with pid 33
2017-06-27 10:12:39,452 INFO success: teamd entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
Traceback (most recent call last):
  File "/usr/bin/supervisord", line 9, in <module>
    load_entry_point('supervisor==3.0', 'console_scripts', 'supervisord')()
  File "/usr/lib/python2.7/dist-packages/supervisor/supervisord.py", line 360, in main
    go(options)
  File "/usr/lib/python2.7/dist-packages/supervisor/supervisord.py", line 370, in go
    d.main()
  File "/usr/lib/python2.7/dist-packages/supervisor/supervisord.py", line 83, in main
    self.run()
  File "/usr/lib/python2.7/dist-packages/supervisor/supervisord.py", line 100, in run
    self.runforever()
  File "/usr/lib/python2.7/dist-packages/supervisor/supervisord.py", line 254, in runforever
    self.reap()
  File "/usr/lib/python2.7/dist-packages/supervisor/supervisord.py", line 288, in reap
    process.finish(pid, sts)
  File "/usr/lib/python2.7/dist-packages/supervisor/process.py", line 455, in finish
    self._assertInState(ProcessStates.STARTING)
  File "/usr/lib/python2.7/dist-packages/supervisor/process.py", line 179, in _assertInState
    self.config.name, current_state, allowable_states))
AssertionError: Assertion failed for start.sh: RUNNING not in STARTING

[jleveque]

Is there any evidence of the system time changing on this machine (e.g., NTP)? It appears as though there is a bug in our version of supervisor (fixed upstream in version 3.2.0) that will cause this error if the system time rolls back after the process starts and before it exits (http://supervisord.org/changes.html#id7).

[lguohan]

yes, it does at the begin is 10:23, and it is 10:12 at the end.

[lguohan]

sorry, are you ask which process changed the time or you just want to confirm the time is changed?

[jleveque]

I just wanted to confirm whether the time had actually rolled back on the system; it appeared that way from the log messages, so I guess it's confirmed.

So, this is a bug in our version of supervisor. Any suggestions on how to proceed?

[lguohan]

upgrade to the latest stable supervisord