archive/tar: write too long

[Aaron Bentley]

Backup seems to be broken; the go tar implementation complains "write too long". This is intermittent.

http://reports.vapour.ws/releases/2671/job/functional-ha-backup-restore/attempt/1909

Issue: http://reports.vapour.ws/releases/issue/555e0e3c749a566239dea516

[Martin Packman (gz)]

New occurrence:

<http://reports.vapour.ws/releases/2876/job/functional-ha-backup-restore/attempt/2169>

[Cheryl Jennings (cherylj)]

This is now being seen by the bootstack team. Bumping to High.

[Mike Deats (mikedeats)]

I am still seeing this bug on Juju 1.25.5 (Trusty)

[Mario Splivalo (mariosplivalo)]

I can confirm this still exists in juju 1.25.6 (trusty).

I bootstrap my environment, juju ssh into the state machine, artificially inflate the log file to over 1GB (using dd to create 512MB file copied from /dev/zero, then cat-ing that file three times to existing all-machines.log file - it generates 1.5G all-machines.log file), then run 'juju backups create', and I get the error:

 ctsmaas:ubuntu@mariosplivalo-bastion:~/tmp/jujulor$ juju backups --debug create
2016-07-29 12:56:00 INFO juju.cmd supercommand.go:37 running juju [1.25.6-trusty-amd64 gc]
2016-07-29 12:56:00 DEBUG juju.api api.go:154 trying cached API connection settings - endpoints [10.230.56.20:17070]
2016-07-29 12:56:00 INFO juju.api api.go:266 connecting to API addresses: [10.230.56.20:17070]
2016-07-29 12:56:00 INFO juju.api apiclient.go:262 dialing "wss://10.230.56.20:17070/environment/f6b2cf9a-432d-454f-830d-0f2c03bcc954/api"
2016-07-29 12:56:00 INFO juju.api apiclient.go:194 connection established to "wss://10.230.56.20:17070/environment/f6b2cf9a-432d-454f-830d-0f2c03bcc954/api"
2016-07-29 12:56:00 DEBUG juju.api api.go:466 API hostnames changed from [10.230.56.20:17070] to [10.230.56.20:17070 rotomvm3.seg:17070] - resolving hostnames
2016-07-29 12:56:00 DEBUG juju.network hostport.go:162 removing unresolvable address "rotomvm3.seg": lookup rotomvm3.seg: no such host
2016-07-29 12:56:00 DEBUG juju.api api.go:497 API addresses unchanged
2016-07-29 12:56:00 DEBUG juju.api api.go:506 cacheChangedAPIInfo: serverUUID="f6b2cf9a-432d-454f-830d-0f2c03bcc954"
2016-07-29 12:56:16 ERROR juju.cmd supercommand.go:429 while creating backup archive: while bundling state-critical files: write to tar file failed: failed to write "/var/log/juju/all-machines.log": archive/tar: write too long
2016-07-29 12:56:16 INFO juju.cmd supercommand.go:435 command finished

Just to confirm, when I do the same with juju 1.24.7, everything works as expected.

[Martin Packman (gz)]

We may not see the symptom on master at present, but the same underlying code issue seems to be present still.

[Martin Packman (gz)]

The issue here is there is a window for the log file to be appended to during the copy of the contents into the backup tar. This is a problem because before the copy starts, the go tar implementation stats the file in order to get the size and write that in the header. Then during write, if too much data is given error is returned. Seems easier to hit with large log files or slow disk.

I have a simple fix that limits the copy length to that at the time of the stat. So, additional messages may not be backed up, but the process continues sanely.

See irclog for more info:

<https://irclogs.ubuntu.com/2016/07/29/%23juju-dev.html#t13:32>

[Martin Packman (gz)]

Fixes applied to the 1.25 and master branches of the utils package:

https://github.com/juju/utils/pull/227
https://github.com/juju/utils/pull/228

The dependency updates for juju are now in review:

https://github.com/juju/juju/pull/5899
https://github.com/juju/juju/pull/5900