[SRU] segfault in log.c code causes phone reboot loops

Note for the record that this bug has so far only been reported on the ubuntu-rtm branch, not the ubuntu branch, of the upstart package. However, the differences between these branches are negligible and include no changes to the upstream code.

I think I see a potential problem if 'initctl notify-disk-writeable' is called multiple times. The log_clear_unflushed() function walks the log_unflushed_files list, attempting to flush each of the logs and freeing them when done with nih_free(). But as far as I know, nih_free() will not cause the element to be removed from the log_unflushed_files list, so if this function is ever called a second time it looks to me that it will re-process the list, traversing freed memory with undefined results.

We can't see anything in the official Ubuntu rootfs that would account for this function being called more than once. On the other hand, we also haven't seen this reproduced on any devices other than those installed in the factory, so it could be that an error has crept in there.

We can try to produce a patch to upstart to fix this bug, to see if it fixes the segfault for those who are seeing it.

I think I understand what's happening now - it's not the log that isn't being freed, it's the list entry the log is attached to that is not freed. The effect is the same though - calling log_clear_unflushed() multiple times could trigger this issue since the still-valid (but incorectly so) list entry is now pointing at potentially garbage memory where a Log used to be.

Test binaries are available here: http://people.canonical.com/~jhunt/upstart/bugs/bug-1447756/armhf/

i386+amd64 are packaged here: https://launchpad.net/~jamesodhunt/+archive/ubuntu/bug-1447756/+packages

I've tried the fix on my bq device and it appears to be in a reboot loop (like the one the fix was supposed to resolve).

As such, I'd recommend testing the binaries only for the session init initially (/usr/bin/ubuntu-touch-session / /usr/share/lightdm/sessions/ubuntu-touch.desktop).

Also, for both system and session scenarios, I'd recommend adding '--debug' to get as much detail as possible.

Something else to try - disable /etc/init/flush-early-job-log.conf on boot...

$ sudo mount -oremount,rw /
$ echo manual | sudo tee /etc/init/flush-early-job-log.override
$ sudo reboot

... and post-boot do the following:

$ for i in $(seq 17); do sudo initctl notify-disk-writeable; done

As Steve has mentioned, we do need to trace down why 'initctl notify-disk-writeable' seems to be being called multiple times on boot though - it should only really be called once when (in the case of Touch) /var/log/ is writable.

Hi ondra/ogra - Can you comment on my suggestions in #6 and #7? My device is still bricked so if you have any suggestions on how to perform a full reset, that'd be great as udf is unable to recover it.

hi James
So one way is to disable upstart logging all together with "--no-log" kern command option. We are going with this option for next OTA, till we can crack actual root cause of this issue.
As for restore, best bet is with MTK flash_tool

I've rebuild the fix in a clean environment and the init binary below now boots fine for me on a bq aquaris E4.5:

http://people.canonical.com/~jhunt/upstart/bugs/bug-1447756/armhf/

i dont think we should close this one, the bu still persists and need to urgently be fixed, the workaround we ship can not stay for log (since it removes all logging for system jobs)

Agreed, either we open new bug to track this, or we don't mark this as fixed. This is the time one could use state "workaround"

DIsabling as a workaround is bug #1452663

ondra and I have been hammering away at this, but progress is painfully slow given that:

a) the problem is not seen on every boot.
b) we can only view the end of kmsg log.
c) rebuild times are relatively slow.

From what ondra says he's seen today, it sounds as though we might be hitting a stack corruption issue - the debug I've given him is not being displayed as expected. Even with the initial fix I created based on code inspection alone, ondra is still seeing exactly the same assertion failure which we thought would have been fixed by the initial fix for this bug.

I've tried various ways to recreate the issue (both on a device and on a normal system, code review / code analysis tools, runtime checkers), but have so far been unsuccessful.

Current work-arounds:

1) Keep using '--no-log' in the kernel command-line.
    Pros: reliable.
   Cons: means that no system jobs get their output logged.

2) Disable the /etc/init/flush-early-job-log.conf job.
    Pros: seems to be reliable (? but needs further testing).
    Cons: means early job output is not logged (however, on the device in question the only output seems to be from /etc/init/container-detect.conf (and that output is not even required).

I think I have nailed it down now, here is brief description what is happening (if I read code right)
There seems to be race, when we get new log data for one of the jobs after job has been terminated, and while processing it we call log_io_reader and eventually log_file_write which will try to flash unflashed buffer to drive.
This succeeds, mind this is before we got disk writable signal.
Since it succeeds, unflashed->len becomes 0, but we don't remove that log instance from list of logs which needs to be flashed (log_unflushed_files).
So next time when we get signal that disk is writable, we try again to flash that log and BOOM it panics on assert checking that log has something to be flashed, but it was already flashed.

Actual change of unfleshed log len changes on line 562, that's where we shrink unflashed buffer by amount we managed to write to disk, which in our case if full len, making buffer after shrinking zero length.
So I can see at least three fixes:
1) we should after calling nih_io_buffer_shrink (log->unflushed, (size_t)wlen); try to check and if log->unflashed->len is 0, and if so then remove it from the log_unflushed_files list.
2) we need to make log_clear_unflushed more tolerant to logs which has been already flushed successfully before reaching to this point.
3) we don't try to flash unfleshed buffers till we get disk writable signal

Sorry in previous comment, replace all "flash" with "flush"
Actually one more issue I can see there is this:
Job dies -> it's added to log_unflushed_files when it has unflushed data
but if job is restarted before we get disk writable signal, it will mess up the things, job will still remain in log_unflushed_files
and once we call log_file_write it will try to flush unflushed data, without removing job from log_unflushed_files list

Hi Ondrej,

Regarding #15, I'm not sure this is correct. As you say, when the job process terminates, job_process_terminated() gets called. This calls log_handle_unflushed() and that function calls log_read_watch(), which ultimately calls write(2). However, even if the write is successful before 'initctl notify-disk-writeable' gets called, if you look at log_handle_unflushed()...

 743 log_handle_unflushed (void *parent, Log *log)
 744 {
 745 NihListEntry *elem;
 746
 747 nih_assert (log);
 748 nih_assert (log->detached == 0);
 749
 750 log_read_watch (log);
 751
 752 if (! log->unflushed->len)
 753 return 1;

So, if the write is successful and log->unflushed->len becomes zero, the function returns 1 (meaning "log does not need to be added to the unflushed list") and crucially the log is not added to the unflushed list.

Hi Ondrej,

Regarding #15, I'm not sure this is correct. As you say, when the job process terminates, job_process_terminated() gets called. This calls log_handle_unflushed() and that function calls log_read_watch(), which ultimately calls write(2). However, even if the write is successful before 'initctl notify-disk-writeable' gets called, if you look at log_handle_unflushed()...

 743 log_handle_unflushed (void *parent, Log *log)
 744 {
 745 NihListEntry *elem;
 746
 747 nih_assert (log);
 748 nih_assert (log->detached == 0);
 749
 750 log_read_watch (log);
 751
 752 if (! log->unflushed->len)
 753 return 1;

So, if the write is successful and log->unflushed->len becomes zero, the function returns 1 (meaning "log does not need to be added to the unflushed list") and crucially the log is not added to the unflushed list.

Regarding #16, there shouldn't be a problem in that scenario since when the log gets added to the unflushed list, it is totally detached from its parent job. Hence, the job can be destroyed but the log lives on as an element of the unflushed list. If that job gets recreated, it will get a new set of log objects associated with it.

Did you manage to get the full log_clear_unflushed() debug output in the end?

So when job gets terminated we don't succeed to write to to the disk and it is added to the unflushed list.
Problem is another call to write function later on, but before we get writable disk signal:
[ 7.460627]init: log_handle_unflushed:778:len=32673, path='/var/log/upstart/ureadahead-touch.log'
[ 7.460682]init: unflushed->len=32673
[ 7.460736]init: job_process_terminated:1877:adding job ureadahead-touch to unflushed list

but then later one we get:
[ 7.968094]init: log_io_reader:368:
[ 7.968158]init: log_file_write:552:unflashed:61817, new_len:150, path:/var/log/upstart/ureadahead-touch.log
[ 7.975087]init: log_file_write:579:unflashed->len:61817, written_len:61817
calling "nih_io_buffer_shrink (log->unflushed, (size_t)wlen);"
[ 7.975167]init: log_file_write:581:unflashed->len:0

and eventually we get:
[ 8.369166]init: control_notify_disk_writeable<<
[ 8.369239]init: log_clear_unflushed<<
[ 8.369280]init: OK checking assert:unflashed->len = 46
[ 8.369435]init: log_clear_unflushed:888:
[ 8.369492]init: log_file_write:552:unflashed->len=46, new:0, path:/var/log/upstart/container-detect.log
[ 8.370305]init: log_file_write:579:len:46, wlen:46
[ 8.370359]init: log_file_write:581:len:0
[ 8.370450]init: OK checking assert:unflashed->len = 0
[ 8.370509]init: log.c:874: Assertion failed in log_clear_unflushed: log->unflushed->len

As you can see call to write in the middle is one causing the issue, since it flushes log buffer, but does not remove it from unflushed list.

So one thing which I still cannot track down is how is that unidentified log_io_reader called. Or who is calling it.
I have put traces to log_read_watch under condition "if (io->recv_buf->len) {" where we call "log_io_reader" but call is not coming from there.
So what are other options for log_io_reader to be called?

Sorry for spamming, but I guess that log_io_reader is called by nih_io_watcher which has been initialised by "nih_io_reopen"
which I suppose is called when job starts?

So that would go back to my original finding, job dies and is restarted before we get signal about disk being writable, but at the time job has been restarted it succeeds in writing unflushed logs to the disk while calling log_io_reader
Makes sense?

the ureadahead-touch upstart job does definitely not need to log anything .... we should add "console none" to it so it does not attempt to. (logging there only makes sense when actively debugging ureadahead anyway)

Ondrej - aha! with the debug, this is making more sense now. Yes, since the ureadahead-touch job spawns a process in the background (ureadahead) and then the job itself exits, the log associated with the main job process gets added to the unflushed list. ureadahead then writes output and the NihIo is automatically serviced to flush the log to disk and set log->unflushed->len to zero. Later, 'initctl notify-disk-writable' gets called and the assert fires as all the output from both /etc/init/ureadahead-touch.conf and from the ureadahead daemon itself has already been logged.

Could you try the following which should be a minimal fix: http://paste.ubuntu.com/11095313/

Another point - the fact that ureadahead-touch is triggering the problem does point to an issue with that job - as can be seen, even when the script section ends (and that associated shell dies), 'ureadahead --daemon' continues and if it produces output, that gets logged. A simple work-around is to remove --daemon so that the job process and the log never become detached.

I can confirm fix: http://paste.ubuntu.com/11095313/ does the job.
It will safely ignore entries of log_unflushed_files list which have log->unflushed->len set to zero. Since we know how this state is reached it seems like previous nih_assert (log->unflushed->len); was too aggressive.

\o/. Yes, Upstart uses asserts extremely agressively. It's unfortunate that we've never hit this issue in testing but I'm currently working on new tests for this slightly unusual scenario.

lp:~jamesodhunt/upstart/bug-1447756-the-actual-fix contains the fix and a new test (which correctly fails with the current lp:upstart but passes with the fix in that branch).

The code has been tested on a failing device and a server system. I am currently testing on a non-failing krillin device. I understand Ondra is going to test on a couple of other devices that exhibit this bug to further sanity check the code.

Once all these tests pass I'll raise an MP for the branch above to get it merged to lp:upstart.

We'll then need to cherry pick the fix into both vivid and wily.

Applying the top 2 commits (r1665 and r1666) from lp:~jamesodhunt/upstart/bug-1447756-the-actual-fix [1] to https://bugs.launchpad.net/ubuntu-rtm/+source/upstart/1.13.2-0ubuntu1rtm1 is now working for me.

I've tested this by building on the device itself and also by building in a ARCH=armhf utopic chroot [2].

__________

[1] - Equivalent to the attached patch.
[2] - Interestingly, building in an vivid ARCH=armhf chroot generates a binary that fails at runtime.

MP raised on lp:upstart to start the trickle-down to the rtm package.

Just to confirm. I just received another device exhibiting boot loop issue and after quick investigation it was same problem, race of chid process continuing logging after parent died but before writable disk signal.
Once I used patched "upstart" binary, device booted normally, so all good.

Looks like kernel bug 1429756 could block 1.13.2-0ubuntu14 landing for wily (being a pre-req to getting this fix into vivid and utopic):

    https://jenkins.qa.ubuntu.com/view/Wily/view/AutoPkgTest/job/wily-adt-upstart/ARCH=amd64,label=adt/9/

@james we can land in vivid first if we need to, and the fix does not need to be made to utopic
We do need the fix to land by May 21

Erroneous test failures can (and should) be overridden in proposed-migration. Also the requirement is not that the package *reach* the development release before being SRUed, only that it be *uploaded* to the development series.

This bug was fixed in the package upstart - 1.13.2-0ubuntu14

---------------
upstart (1.13.2-0ubuntu14) wily; urgency=medium

  * Cherry-pick upstream fix for LP: #1447756, fixing broken handling
    when flushing logs to disk.
  * Cherry-pick follow-on upstream fix for LP: #1447756.

 -- James Hunt <email address hidden> Mon, 18 May 2015 11:09:10 +0100

Thanks for nudging -proposed Steve.

I've silo 021 now includes upstart version 1.13.2-0ubuntu13.1 (which sil2100 synced from wily).

Basic test plan is here: https://wiki.ubuntu.com/Process/TestPlans/upstart-bug-1447756

I've tested this as follows:

$ wget http://people.canonical.com/~jhm/barajas/recovery.img
$ ubuntu-device-flash --verbose touch --bootstrap --channel=ubuntu-touch/rc-proposed/bq-aquaris.en --device krillin --recovery-image ./recovery.img
$ citrain device-upgrade 021

I then reflashed the boot.img using one from ondra which drops the current '--no-log' option from /proc/cmdline and rebooted.

As far as I'm concerned, the fix is good. All that now remains is for ondra or one of the folk in London who have the "failing" krillin devices to test the above.

Unfortunately, ondra no longer has the failing phones so we may need to take a decision to just land this if QA are happy the change has not regressed the behaviour for non-failing phones.

I've tried to raise QA but they are sprinting in the US this week so no direct response.

I believe that sil2100 is doing what he can atm, but it's unclear whether this fix will make it into the next OTA at this stage.

Per Ondrej on private bug https://bugs.launchpad.net/barajas/+bug/1439778/comments/30
"I can confirm that phone which we received from BQ had same issue and problem has been resolved once applied fix developed in bug #1447756 was applied.
We should now revert workaround committed as part of Bug #1452663"

Is the fix landing in vivid?

On Thu, May 21, 2015 at 05:05:16PM -0000, Alex Kaluzhny wrote:
> Is the fix landing in vivid?

The fix has landed in the stable phone overlay ppa (upstart
1.13.2-0ubuntu13.1).

James, can you please follow through on SRUing this to vivid? I've copied
the package into the vivid-proposed queue from the stable-phone-overlay ppa.

--
Steve Langasek Give me a lever long enough and a Free OS
Debian Developer to set it on, and I can move the world.
Ubuntu Developer http://www.debian.org/
<email address hidden> <email address hidden>

Hi Steve - ah, sorry - hadn't registered that you'd already copied the package into the queue (we now have 2 :-) Could mine be deleted please?

On Fri, May 22, 2015 at 01:34:52PM -0000, James Hunt wrote:
> Hi Steve - ah, sorry - hadn't registered that you'd already copied the
> package into the queue (we now have 2 :-) Could mine be deleted please?

Done.

What about the fix for Trusty? I have similar problems with upstart=1.12.1-0ubuntu4.2.
Workrounds with kernel option "--no-log" and disabling flush-early-job-log job works for me.

There was no intention of fixing this bug for trusty, because this bug was never reported with trusty. It has only been reported with the Ubuntu phone, which is utopic or later. If you are experiencing crashes with upstart on trusty, can you please attach a tarball of the /etc/init directory from the affected system?

Hello Oliver, or anyone else affected,

Accepted upstart into vivid-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/upstart/1.13.2-0ubuntu13.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

As a part of the Stable Release Updates quality process a search for Launchpad bug reports using the version of upstart from vivid-proposed was performed and bug 1470745 was found. Please investigate this bug report to ensure that a regression will not be created by this SRU. In the event that this is not a regression remove the "verification-failed" tag from this bug report and tag 1470745 "bot-stop-nagging". Thanks!

The version of upstart in the proposed pocket of Vivid that was purported to fix this bug report has been removed because the bugs that were to be fixed by the upload were not verified in a timely (105 days) fashion.

Please backport this to trusty, it hit me there, too. Standard amd64 desktop.

Yep, this is definitely affecting Trusty as well. Is there any chance the fix will be backported?

Ping?

Justin, please see comment #42. Can you provide a reproducer for this on trusty?

That this has not been widely reported on 14.04 means it has not been a priority for fixing; less so now that a newer LTS release is available.

Not really. The bug is hugely intermittent as it stands.

However, I can confirm we're experiencing this on our fleet.

Guys, this really is affecting us. Help?

This won't make progress as an SRU without a reproducer for the bug. An intermittent reproducer would be better than no reproducer.

I understand. However, our reproducer is: boot.
Removing --daemon from the ureadahead initscripts does appear to reduce the frequency with which this occurs.

Guys, please help us with this. This is a real problem, which is low-probability but high-frustration.