Plugin keeps forgetting my access token

[seltix5]

For some reason the plugin forgets the access token. I could not find out exactly what is causing this problem...

any help?

thank you.

[CoDanny]

Have you crated your box as a clone from another?

[seltix5]

No. It's my first and only raspberry pi 3 b+ brand new installation from the octoprint site

[CoDanny]

It might be an interaction with another plugin. Can you see if this happens when all other plugins disabled? Also when does it forget ?

[seltix5]

it could be. as I said, I could not find out what exactly is causing the problem. it normally works for some days and then it stops working because the access token is not there anymore. disabling all plugins for that long is not really convenient... :S and since I did not find out what is the root problem even if I disabled all plugins I will not know if its still working because I disabled all plugins or just by luck...

[CoDanny]

knowing which plugin could potentially affect our plugin would help us narrow down the problem. We can't fix this without the help of people affected as we can't make this happen in our lab and it doesn't happen for the majority of our users. The key to fixing this problem is to find out what is different in the environment of those affected.

A similar bug was found to be caused by cloning SD cards which made two boxes use the same box id and thus conflict with each other when connecting to our severs. The result was that the system would kick one of them out. However you mentioned that this was a brand new install. We need to see what else in your installation causes this.

[seltix5]

Hello, I will try to disable all add-ons trying to isolate the problem. This will take probably some weeks depending on the prints I will do and I will report back with some results. Can I just disable the modules or should I uninstall them?

[CoDanny]

You can start with disabling. I think that should be enough.

Thanks for your help!

[seltix5]

hello, It just append again today.

My active plugins are :

• AstroPrint (1.3.2)
• Octolapse (0.3.4) (this one cant be the reason since it was disabled when it append the other times)
• PSU Control (0.1.8)
• TouchUI (0.3.13)

OctoPrint 1.3.11 running on OctoPi 0.16.0

[CoDanny]

can you try disabling PSU Control first and see if it happens again?

[seltix5]

i only installed psu control this week but sure I will disable them all..

[seltix5]

hello, it just did. this morning when I power up my print and octopi the key was lost... the only plugin enabled is astroprint

[seltix5]

hello, it justs forgot the key again today. it's almost like each time I try to connect to my printer from outsite, (from a public wifi like today) it forgets the key...

[CoDanny]

How do you do that? Do you have access to your OctoPrint instance from outside your network?

[seltix5]

how I did that? trying to use astroprint... isnt that one of the points of using astroprint?

[CoDanny]

I thought you meant you tried to access your OctoPI box from outside the network. Not via AstroPrint but directly to the box. I was just asking clarification

[seltix5]

Oh OK. No, I only login to my astroprint account from the browser. Yesterday it was working. I shutdown the printer and the Pi for the night. This morning I power it up both before living the house, the when I login for the first time today to my astroprint account to start a print from a public wifi the printer was not there anymore.

[CoDanny]

Are you able to send me logs from the octopi? You can create a ticket here if you rather do this offline: https://astroprint.zendesk.com/hc/en-us/requests/new

[seltix5]

That's fine by me, I can attach the logs here or create the ticket if you prefer. What logs do you need and I do I get them?

[CoDanny]

The main octoprint log. I think there's a way to see them and download from settings.

[seltix5]

here it is. octoprint.log

[CoDanny]

I can see some relevant lines:

2019-08-22 07:39:32,159 - octoprint.plugins.astroprint - INFO - There was an error loading /home/pi/.octoprint/data/astroprint/print_files.yaml:
Traceback (most recent call last):
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint_astroprint/AstroprintDB.py", line 49, in getPrintFiles
    with open(self.infoPrintFiles, "r") as f:
IOError: [Errno 2] No such file or directory: '/home/pi/.octoprint/data/astroprint/print_files.yaml'
2019-08-22 07:39:32,224 - octoprint.plugins.astroprint - INFO - No user logged to AstroPrint

Is there anything on the /home/pi/.octoprint/data/astroprint directory

[seltix5]

only one file "user.yaml" with the content "user: null"

[seltix5]

I just insert the api token again and this file was updated with :

user:
  accessKey: <removed>
  email: frygvk@tznvy.pbz
  expires: 1567202991.0
  id: <removed>
  last_request: 1567199391.0
  name: Bruno
  refresh_token: <removed>
  token: <removed>

[CoDanny]

Just want to make sure of one thing: You edited this to some private info, correct. That wasn't literally what was on the file.

[seltix5]

Yes I removed the private keys and replace with "< removed >"

[CoDanny]

I have also seen this in your logs

2019-08-28 21:11:55,295 - octoprint.plugins.astroprint - ERROR - Failed to send print_job request: HTTPSConnectionPool(host='api.astroprint.com', port=443): Max retries exceeded with url: /v2/print-jobs/4aed16fedfb24d37b39fdc442817d7f1 (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x6425b290>: Failed to establish a new connection: [Errno 110] Connection timed out',))
2019-08-28 21:16:21,535 - octoprint.plugins.astroprint - ERROR - Failed to send print_job request: HTTPSConnectionPool(host='api.astroprint.com', port=443): Max retries exceeded with url: /v2/print-jobs (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x643ea630>: Failed to establish a new connection: [Errno 110] Connection timed out',))
2019-08-28 21:34:55,949 - octoprint.plugins.astroprint - ERROR - Error connecting to boxrouter: [Errno -3] Temporary failure in name resolution

This indicates that sometimes there are problems with your network reaching our servers. This might cause use log out. We're still investigating.

[seltix5]

this specific day around that time I did lose internet (ISP problem) I dont think it's related since it append only that day

[CoDanny]

Ok. I also found this:

2019-08-27 23:03:47,372 - octoprint.plugins.astroprint - WARNING - Unautorized token, AstroPrint user logged out.

Do you ever log the user out yourself? If not, this might a place I can look deeper. See options why this might be trigger by itself.

[CoDanny]

Is the same astroprint user used in another octoprint box?

[seltix5]

it may be it. I did not logout myself and i'm using only astroprint in this box

[CoDanny]

We have a lead. There will be new release next week

[seltix5]

updated log, it lost the key again. the same "WARNING - Unautorized token, AstroPrint user logged out." error append.

octoprint.log

[CoDanny]

@seltix5 Version 1.3.3 was released today. Could you please update and let me know if this happens again?

[seltix5]

hello. plugin updated, logs cleaned and key set again. Lets see if it stays logged this time. thanks :D I will report in a few days if all works well.

[seltix5]

hello, now I dont get any printing information, is that normal?

[CoDanny]

No, sorry this happens when trying to get software out fast :(

[CoDanny]

Emergency release 1.3.4 done

[seltix5]

hi, np =) its working again, thanks :D let's hope the token problem is gone too :+1:

[seltix5]

hello, key lost again :S octoprint.log

[CoDanny]

This seems to be a different cause. Here's the relevant portion of the log to keep for historical reasons:

2019-09-04 23:17:28,237 - octoprint.plugins.astroprint - INFO - There was an error loading /home/pi/.octoprint/data/astroprint/print_files.yaml:
Traceback (most recent call last):
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint_astroprint/AstroprintDB.py", line 49, in getPrintFiles
    with open(self.infoPrintFiles, "r") as f:
IOError: [Errno 2] No such file or directory: '/home/pi/.octoprint/data/astroprint/print_files.yaml'
2019-09-04 23:17:28,729 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2019-09-04 23:17:28,765 - octoprint.plugins.astroprint - INFO - User Bruno logged to AstroPrint
2019-09-04 23:17:28,766 - octoprint.plugins.astroprint - INFO - Getting AstroPrint user info
2019-09-04 23:17:29,025 - octoprint.plugins.tracking - INFO - Sent tracking event ping, payload: {'octoprint_uptime': 15}
2019-09-04 23:17:29,404 - octoprint.plugins.tracking - INFO - Sent tracking event startup, payload: {'python': '2.7.13', 'ram': 917016576, 'octopi_version': '0.16.0', 'version': u'1.3.11', 'pip': '19.0.1', 'cores': 4, 'freq': 1400.0, 'pi_model': 'Raspberry Pi 3 Model B Plus Rev 1.3', 'os': 'linux'}
2019-09-04 23:17:29,596 - octoprint.plugins.astroprint - WARNING - Unautorized token, AstroPrint user logged out.

We will continue to look at this @seltix5. Thanks for all your help!

[seltix5]

hello, glad to help. that error was already visible on the previous log, but this one appears to be new :

2019-09-03 08:38:36,082 - octoprint - ERROR - Exception on /plugin/astroprint/accessKeys [POST]
Traceback (most recent call last):
  File "/home/pi/oprint/local/lib/python2.7/site-packages/flask/app.py", line 1817, in wsgi_app
    response = self.full_dispatch_request()
  File "/home/pi/oprint/local/lib/python2.7/site-packages/flask/app.py", line 1477, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "/home/pi/oprint/local/lib/python2.7/site-packages/flask/app.py", line 1381, in handle_user_exception
    reraise(exc_type, exc_value, tb)
  File "/home/pi/oprint/local/lib/python2.7/site-packages/flask/app.py", line 1475, in full_dispatch_request
    rv = self.dispatch_request()
  File "/home/pi/oprint/local/lib/python2.7/site-packages/flask/app.py", line 1461, in dispatch_request
    return self.view_functions[rule.endpoint](**req.view_args)
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint_astroprint/__init__.py", line 525, in getAccessKeys
    ws_token=create_ws_token(self.user['id']))
  File "/home/pi/oprint/local/lib/python2.7/site-packages/octoprint_astroprint/__init__.py", line 62, in create_ws_token
    s = URLSafeTimedSerializer(octoprint.server.UI_API_KEY)
AttributeError: 'module' object has no attribute 'UI_API_KEY'
2019-09-03 08:38:36,094 - tornado.access - ERROR - 500 POST /plugin/astroprint/accessKeys (::ffff:192.168.168.104) 30.98ms
2019-09-03 08:38:36,491 - tornado.access - WARNING - 403 GET /plugin/astroprint/api/printer-profile?apiKey=undefined (::ffff:192.168.168.104) 15.73ms
2019-09-03 08:39:32,020 - octoprint.util.comm - INFO - Telling the printer to set the busy interval to our "communicationBusy" timeout - 1s = 2s
2019-09-03 08:48:31,641 - octoprint.server.heartbeat - INFO - Server heartbeat <3

[seltix5]

hi, key lost again, diferent error : 2019-09-06 05:50:26,297 - octoprint.plugins.astroprint - WARNING - Unautorized token, AstroPrint user logged out. octoprint.log

[CoDanny]

It's actually the same error we're already looking into. One question. Do you also access astroprint and your box via our mobile app?

[seltix5]

I do have the app installed and configured yes.

[CoDanny]

I think I found the problem in your system. Your system clock goes back. This will certainly mess with our token refresh sequence as you will be allowed to use a token that has expired with the subsequent access denied error and log out. Here's the proof from your logs:

The last successful token use before the logout:

2019-09-06 05:51:59,016 - octoprint.plugins.astroprint - INFO - Bruno logged to AstroPrint

The access that creates the logout:

2019-09-06 05:50:26,297 - octoprint.plugins.astroprint - WARNING - Unautorized token, AstroPrint user logged out.

As you can see the from the log timestamp, the system clock is one minute earlier than the previous log even though it's at least 5 minutes later.

The jump back happens here:

2019-09-06 05:55:39,800 - octoprint.plugins.astroprint - INFO - Boxrouter connected to astroprint service
2019-09-06 05:50:06,543 - octoprint.startup - INFO - ******************************************************************************
2019-09-06 05:50:06,545 - octoprint.startup - INFO - Starting OctoPrint 1.3.11

This is likely a restart of OP.

You need to install NTP or some other clock sync software in order to keep the clock accurate otherwise there's really no way we can operate. We need to know the time you acquired your access token, when the token expires and the current date.

[seltix5]

hello, is this a normal situation? octopi does not keep time updated?

thank you.

[CoDanny]

I doubt this is normal. This is one reason we have never been able to reproduce this problem ourselves and over 98% of our users don't have it. It might be related to your network maybe blocking NTP? or underpower in the device that makes the clock slow. I don't really know the cause of this but I do know it's not common and it explains your problem.

[seltix5]

ok, this is realy strange. thank you. I will search further about this problem and I will post my finding for future reference and it may help others, is that ok?

I start by setting the correct timezone and wifi country, it was the default from the instalation (https://github.com/Javierma/OctoPrint-TFG/wiki/Setup-the-system-clock-using-raspi-config)

[seltix5]

ps : about those other not related errors (There was an error loading /home/pi/.octoprint/data/astroprint/print_files.yaml), is it normal? thanks

[CoDanny]

Yes, please post anything you find out here. The print_files.yaml if you don't have print files from the cloud in your pi. However we might make the error log a bit less scary.