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 when job gets terminated we don't succeed to write to to the disk and it is added to the unflushed list. unflushed: 778:len= 32673, path='/ var/log/ upstart/ ureadahead- touch.log' >len=32673 terminated: 1877:adding job ureadahead-touch to unflushed list
Problem is another call to write function later on, but before we get writable disk signal:
[ 7.460627]init: log_handle_
[ 7.460682]init: unflushed-
[ 7.460736]init: job_process_
but then later one we get: write:552: unflashed: 61817, new_len:150, path:/var/ log/upstart/ ureadahead- touch.log write:579: unflashed- >len:61817, written_len:61817 buffer_ shrink (log->unflushed, (size_t)wlen);" write:581: unflashed- >len:0
[ 7.968094]init: log_io_reader:368:
[ 7.968158]init: log_file_
[ 7.975087]init: log_file_
calling "nih_io_
[ 7.975167]init: log_file_
and eventually we get: notify_ disk_writeable< < unflushed< < unflashed- >len = 46 unflushed: 888: write:552: unflashed- >len=46, new:0, path:/var/ log/upstart/ container- detect. log write:579: len:46, wlen:46 write:581: len:0 unflashed- >len = 0 unflushed: log->unflushed->len
[ 8.369166]init: control_
[ 8.369239]init: log_clear_
[ 8.369280]init: OK checking assert:
[ 8.369435]init: log_clear_
[ 8.369492]init: log_file_
[ 8.370305]init: log_file_
[ 8.370359]init: log_file_
[ 8.370450]init: OK checking assert:
[ 8.370509]init: log.c:874: Assertion failed in log_clear_
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.