upstart

  1. Bug #388873
  2. Comment #26

Comment 26 for bug 388873

Revision history for this message
Scott James Remnant (Canonical) (canonical-scott) wrote : Re: init: segfault after changing date

Thanks very much for all your help so far.

From the logs, this looks like the key moment:

May 17 15:13:32 sonostation-usb26-eth init: Handling started event
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_ssm goal changed from stop to start
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_ssm state changed from waiting to starting
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_ssm respawning too fast, stopped
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_ssm respawning too fast, stopped
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_ssm goal changed from start to stop
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_ssm state changed from starting to waiting
May 17 15:13:32 sonostation-usb26-eth init: event_emit: Pending stopped event

This starting event is "started ezono-cyclades-t_smr", which we've established is the one that is unexpectedly freed.

Two things strike me about this:

 - "respawning too fast" - this wrongly uses the system time, so is one of the very few things to be broken by spooling the clock back a day

 - there's two of them printed, that's odd...

The next sequence of log message is everything else starting from this event:

May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-stop-software-control goal changed from stop to start
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-stop-software-control state changed from waiting to starting
May 17 15:13:32 sonostation-usb26-eth init: event_emit: Pending starting event
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_dso goal changed from stop to start
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_dso state changed from waiting to starting
May 17 15:13:32 sonostation-usb26-eth init: event_emit: Pending starting event
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_ssc goal changed from stop to start
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_ssc state changed from waiting to starting
May 17 15:13:32 sonostation-usb26-eth init: event_emit: Pending starting event
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_fem goal changed from stop to start
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_fem state changed from waiting to starting
May 17 15:13:32 sonostation-usb26-eth init: event_emit: Pending starting event
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_cal goal changed from stop to start
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_cal state changed from waiting to starting
May 17 15:13:32 sonostation-usb26-eth init: event_emit: Pending starting event
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_prd goal changed from stop to start
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_prd state changed from waiting to starting
May 17 15:13:32 sonostation-usb26-eth init: event_emit: Pending starting event
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_scp goal changed from stop to start
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_scp state changed from waiting to starting
May 17 15:13:32 sonostation-usb26-eth init: event_emit: Pending starting event
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_ltl goal changed from stop to start
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_ltl state changed from waiting to starting
May 17 15:13:32 sonostation-usb26-eth init: event_emit: Pending starting event
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_fbs goal changed from stop to start
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_fbs state changed from waiting to starting
May 17 15:13:32 sonostation-usb26-eth init: event_emit: Pending starting event
May 17 15:13:32 sonostation-usb26-eth runuser: pam_unix(runuser-l:session): session closed for user x
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_ime goal changed from stop to start
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-t_ime state changed from waiting to starting
May 17 15:13:32 sonostation-usb26-eth init: event_emit: Pending starting event
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-usb-storage goal changed from stop to start
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-usb-storage state changed from waiting to starting
May 17 15:13:32 sonostation-usb26-eth init: event_emit: Pending starting event

We then see two previous "started" events get handled, along with the "stopped" event for ezono-cyclades-t_ssm

May 17 15:13:32 sonostation-usb26-eth init: Handling started event
May 17 15:13:32 sonostation-usb26-eth init: Handling started event
May 17 15:13:32 sonostation-usb26-eth init: Handling stopped event

Then the starting events for those all get handled:

May 17 15:13:32 sonostation-usb26-eth init: Handling starting event
May 17 15:13:32 sonostation-usb26-eth init: Handling starting event
May 17 15:13:32 sonostation-usb26-eth init: Handling starting event
May 17 15:13:32 sonostation-usb26-eth init: Handling starting event
May 17 15:13:32 sonostation-usb26-eth init: Handling starting event
May 17 15:13:32 sonostation-usb26-eth init: Handling starting event
May 17 15:13:32 sonostation-usb26-eth init: Handling starting event
May 17 15:13:32 sonostation-usb26-eth init: Handling starting event
May 17 15:13:32 sonostation-usb26-eth init: Handling starting event
May 17 15:13:32 sonostation-usb26-eth init: Handling starting event
May 17 15:13:32 sonostation-usb26-eth init: Handling starting event

Finally we expect to see the above set finish:

May 17 15:13:32 sonostation-usb26-eth init: event_finished: Finished started event
May 17 15:13:32 sonostation-usb26-eth init: event_finished: Finished started event
May 17 15:13:32 sonostation-usb26-eth init: event_finished: Finished started event
May 17 15:13:32 sonostation-usb26-eth init: event_finished: Finished stopped event

If you're counting, you'll notice that there are THREE "started" events being finished, not TWO as we expect. Upstart is incorrectly finishing and freeing the "started t_smr" event!

We'd next expect to see a starting event being finished, leading to a process being started:

May 17 15:13:32 sonostation-usb26-eth init: event_finished: Finished starting event
May 17 15:13:32 sonostation-usb26-eth init: ezono-cyclades-stop-software-control state changed from starting to pre-start
May 17 15:13:32 sonostation-usb26-eth kernel: init[1]: segfault at 3c ip 00c7c6b3 sp bfa3c48c error 4 in libc-2.8.so[c07000+163000]

We do, and that causes the segfault.

So there we go, Upstart has incorrectly freed the "started t_smr" event. This must be a bug in the respawn failure handling, either over or under-reffing the emission.

I've filed bug #389586 to track the fact that respawn uses a non-monotonic clock separately, as well as bug #389588 to track another potential issue and bug #389589 for the underlying issue of that.

These should just cause bad behaviour, not a segfault - the segfault is being caused (I believe) by the respawn handling - it just happens that the date change is a handy way to trigger that