Update fails once and then succeed, everytime.

[gege2b]

Hi all,
I ran into the same issue everytime OctoPrint try to update.
Running on Raspberry pi 1 model B with raspbian jessie

details below

What were you doing?

Click on the update button when the notification pops up

What did you expect to happen?

The update run with success

What happened instead?

The update fails once, then it success if launched right after from the "software update" menu

Branch & Commit or Version of OctoPrint

Version: 1.3.0.dev1518+gd28e098 (devel branch)
Tying to upgrade to 1.3.0.dev1525+gfac83e9 (devel branch)

But I got this issue many time in the past with older version (but always devel)

Printer model & used firmware incl. version

not related

Browser and Version of Browser, Operating System running Browser

Firefox 49.0.2 on Windows 10

Link to octoprint.log

Octoprint log : http://pastebin.com/ivSGV7nd

Software update log : http://pastebin.com/Y7WvgeYa
Note : I also included the failed and succeeded updates from yesterday so you could see two occurences of the same issue

I have read the FAQ.

thank you

[foosel]

Based on the logs it looks like it was hiccuping on an encoding problem due to some non-ASCII character in the output of git pull during the update. That also explains why it runs through the second time, since then the git pull has run already (only its output wasn't captured). I have not been able to reproduce this, but I just pushed the above commit 2c6fb68 that should hopefully still solve this. So once you are updated to OctoPrint 1.3.0.dev1529+g2c6fb68 or later, the updates should no longer show that initial error I hope.

On your automatic restart issue I'm currently drawing a blank. I made the error message in that case more verbose, maybe that will help finding the cause. I cannot reproduce the behaviour. So if you are still seeing this after updating, please open a new ticket (always: one ticket per issue - multiple issues per ticket cause chaos).

[gege2b]

Hi, thank you !

I'll confirm this is/isn't working on Monday when I'm back to work (but I'm pretty confiant it will work :)

The restart issue was actually just a note inside the log, of course if it still here on monday I'll open a new ticket

[foosel]

Just keep in mind that you'll only be able to confirm it working on the first update you run AFTER updating to OctoPrint 1.3.0.dev1529+g2c6fb68 or later, I naturally cannot apply patches retroactively ;)

[gege2b]

Hi there
Yeah, I update too lately yesterday and there was no other commit later to try it out :)

Just updated right now, still get the same type of error but not at the same place...

It does the git pull stuff right (the problematic string was certainly "Mise à jour ..." - french system), I saw all the byte-compiling stuff in octoprint log windows and then :

2016-11-15 10:36:02,912 - octoprint.plugins.softwareupdate - ERROR - Update of octoprint can not be performed
Traceback (most recent call last):
  File "/home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.0.dev1532_gc6b8b17-py2.7.egg/octoprint/plugins/softwareupdate/__init__.py", line 747, in _perform_update
    update_result = updater.perform_update(target, populated_check, target_version, log_cb=self._log)
  File "/home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.0.dev1532_gc6b8b17-py2.7.egg/octoprint/plugins/softwareupdate/updaters/update_script.py", line 88, in perform_update
    caller.checked_call(update_command, cwd=folder)
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/OctoPrint-1.3.0.dev1532_gc6b8b17-py2.7.egg/octoprint/util/commandline.py", line 63, in checked_call
    returncode, stdout, stderr = self.call(command, **kwargs)
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/OctoPrint-1.3.0.dev1532_gc6b8b17-py2.7.egg/octoprint/util/commandline.py", line 96, in call
    self._log_stdout(*lines)
  File "/home/pi/OctoPrint/venv/local/lib/python2.7/site-packages/OctoPrint-1.3.0.dev1532_gc6b8b17-py2.7.egg/octoprint/util/commandline.py", line 119, in _log_stdout
    self.on_log_stdout(*lines)
  File "/home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.0.dev1532_gc6b8b17-py2.7.egg/octoprint/plugins/softwareupdate/updaters/update_script.py", line 21, in _log_stdout
    _log(lines, prefix=">", stream="stdout")
  File "/home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.0.dev1532_gc6b8b17-py2.7.egg/octoprint/plugins/softwareupdate/updaters/update_script.py", line 29, in _log
    log_cb(lines, prefix=prefix, stream=stream)
  File "/home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.0.dev1532_gc6b8b17-py2.7.egg/octoprint/plugins/softwareupdate/__init__.py", line 885, in _log
    self._console_logger.debug(u"{prefix} {line}".format(**locals()))
UnicodeDecodeError: 'ascii' codec can't decode byte 0xc3 in position 5: ordinal not in range(128)

Running the upgrade again worked fine

plugins_softwareupdate_console.log seems to miss all the part where the error appeared but it has the one who succeeded :

First update attempt :
2016-11-15 10:33:39,032   /home/pi/OctoPrint/venv/bin/python "/home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.0.dev1532_gc6b8b17-py2.7.egg/octoprint/plugins/softwareupdate/scripts/update-octoprint.py" --branch= --force=false "/home/pi/OctoPrint" 06f7abdb2d35699c55ac2aef30d4290b6dacd3dd
2016-11-15 10:34:58,244 > Python executable: '/home/pi/OctoPrint/venv/bin/python'
2016-11-15 10:34:59,941 > >>> Running: git diff --shortstat
2016-11-15 10:34:59,946 > > git diff --shortstat
2016-11-15 10:34:59,951 > >>> Running: git fetch
2016-11-15 10:34:59,955 > > git fetch
2016-11-15 10:34:59,960 > []
2016-11-15 10:34:59,964 > >>> Running: git pull
2016-11-15 10:34:59,969 > > git pull

It failed somewhere here but logs shows nothing.
If you take a look at the timestamp of the error above, you can see it's ~one minute later than  the last git pull. All stuff done during this time was lost/not logged

Second update attempt:
2016-11-15 10:38:01,435   /home/pi/OctoPrint/venv/bin/python "/home/pi/OctoPrint/venv/lib/python2.7/site-packages/OctoPrint-1.3.0.dev1532_gc6b8b17-py2.7.egg/octoprint/plugins/softwareupdate/scripts/update-octoprint.py" --branch= --force=false "/home/pi/OctoPrint" 06f7abdb2d35699c55ac2aef30d4290b6dacd3dd
2016-11-15 10:39:18,668 > Python executable: '/home/pi/OctoPrint/venv/bin/python'
2016-11-15 10:39:18,686 > >>> Running: git diff --shortstat
2016-11-15 10:39:18,696 > > git diff --shortstat
2016-11-15 10:39:18,714 > >>> Running: git fetch
2016-11-15 10:39:18,726 > > git fetch
2016-11-15 10:39:18,737 > []
2016-11-15 10:39:18,763 > >>> Running: git pull
2016-11-15 10:39:18,775 > > git pull
2016-11-15 10:39:18,790 > Already up-to-date.
2016-11-15 10:39:18,821 > >>> Running: python setup.py clean
2016-11-15 10:39:18,830 > > /home/pi/OctoPrint/venv/bin/python setup.py clean
2016-11-15 10:39:18,842 > running clean
2016-11-15 10:39:18,861 > Deleting build directory
2016-11-15 10:39:18,875 > Deleted /home/pi/OctoPrint/src/octoprint_setuptools/__init__.pyc
2016-11-15 10:39:18,891 > >>> Running: python setup.py install
2016-11-15 10:39:18,913 > > /home/pi/OctoPrint/venv/bin/python setup.py install
2016-11-15 10:39:18,920 > running install
2016-11-15 10:39:18,936 > running bdist_egg
2016-11-15 10:39:18,947 > running egg_info
2016-11-15 10:39:18,957 > writing requirements to src/OctoPrint.egg-info/requires.txt
(...)
- success -

At least, I didn't had restart issue this time ;)

[foosel]

Damn. Probably same issue, different location though. And yeah, it crashes while trying to write out the problematic log line(s), so there's nothing in the log. I guess I'll spend some more time on that one ;)

[foosel]

Ok, I think I found and fixed the culprit (and I hope that was the last one of those). OctoPrint 1.3.0.dev1543+g174ffdf and later should be fixed. Let's see :)

[gege2b]

Hi !
It's OK now. As intended it failed this morning for the first update because patch wasn't applied yet, but I updated right now for the two latest commit and it was all OK

Thank you both for this awsome software and your reactivity !

I let you close this issue in case you want it to stay open for any reason

[foosel]

Perfect, thanks for getting back to me on this! Also thanks for spotting this, that would have caused a lot of people issues once 1.3.0 gets released. I'll leave this open until it's released as part of the next RC, but I'll mark it as solved :)

[foosel]

1.3.0rc2 is out