Session | KeyError: storage_scenario

[tweak-wtf]

Hey folks,

since yesterday I get the following error when trying to connect to the ftrack_api.

// ftrack_api.session.Session : Calling server https://[OUR_FTRACK_SITE]/api with '[{"action": "query_server_information"}]' // 
// ftrack_api.session.Session : Call took: 0.113607 // 
// ftrack_api.session.Session : Response: u'[{"storage_scenario": {"data": {}, "scenario": "ftrack.automatic"}, "schema_hash": "450f452f8addcd23370a8a90f8156c4a", "version": "4.1.5.4750", "is_timezone_support_enabled": false}]' // 
// Error: ftrack_api.session.Session : Server reported error in unexpected format. Raw error was: [{"storage_scenario": {"data": {}, "scenario": "ftrack.automatic"}, "schema_hash": "450f452f8addcd23370a8a90f8156c4a", "version": "4.1.5.4750", "is_timezone_support_enabled": false}] // 
# Traceback (most recent call last):
#   File "/prod/softprod/apps/maya/2018/linux/lib/python27.zip/logging/__init__.py", line 853, in emit
#     msg = self.format(record)
#   File "/prod/softprod/apps/maya/2018/linux/lib/python27.zip/logging/__init__.py", line 726, in format
#     return fmt.format(record)
#   File "/users_roaming/tdorfmeister/devel/ppStudio/common/libs/filmmore/logger.py", line 48, in format
#     logline = super(self.__class__, self).format(record)
#   File "/prod/softprod/apps/maya/2018/linux/lib/python27.zip/logging/__init__.py", line 465, in format
#     record.message = record.getMessage()
#   File "/prod/softprod/apps/maya/2018/linux/lib/python27.zip/logging/__init__.py", line 325, in getMessage
#     msg = str(self.msg)
#   File "/prod/softprod/libs/ftrack_api/exception.py", line 42, in __str__
#     return str(self.message.format(**keys))
# KeyError: '"storage_scenario"'

I'm just trying to connect using `ftrack_api.Session()` with my credentials and `auto_connect_event_hub=True`.

Any help is much appreciated, since I really have no clue how to figure this one out on my own.

Thanks

 

PS: I should note that my api is on v1.3.3. I know... 😕

 

[Lorenzo Angeli]

Hi @tweak-wtf sorry to see you are having problems.

The error seems to be coming from a wrong deserialization of the server response (json) relative to the storage scenario.
This could be caused by a variety of things related to the network itself (proxy, firewall etc....)

Could you please check if any of these changes have been put in place before this error have started happening ? 
I've trying to replicate it with you same version of the ftrack-python-api without success so far.
 

Looking forward to hear more from you !
In the meanwhile we'll keep looking for other potential reasons.

L.

 

 

[Lorenzo Angeli]

@tweak-wtf could you please try with a simple standalone python script rather than from within maya to see if you can replicate ?
Thanks !

[tweak-wtf]

Hi @Lorenzo Angeli
thanks for responding. Sure... I also sent an eMail with some insights to support so I'll just summarize what I wrote in that eMail.

Currently I'm trying to build a 3D pipeline based on pyblish also integrating the published files with ftrack. For that I need to connect to ftrack API from a pyblish plugin.
The error was popping up 2 days ago. Before that everything was working as normal. I talked to our SysAdmin and he told me that he didn't change anything about the network settings.

The error only happens when trying to establish a connection from that pyblish plugin... Trying to connect from just a standard python interpreter ran from the terminal works.

I went ahead and added some lines that log some variables to a file to the session.py in the ftrack_api python package in order to see what's going on.
The output that I'm getting is the following:

Trying to connect from terminal...
############# DATA ##########
[{"action": "query_server_information"}]
############# RESULT ##########
[{u'storage_scenario': {u'data': {}, u'scenario': u'ftrack.automatic'}, u'version': u'4.1.5.4750', u'is_timezone_support_enabled': False, u'schema_hash': u'450f452f8addcd23370a8a90f8156c4a'}]


Trying to connect from pyblish plugin...
############# DATA ##########
[{"action": "query_server_information"}]
############# RESULT ##########
[{u'storage_scenario': {u'data': {}, u'scenario': u'ftrack.automatic'}, u'version': u'4.1.5.4750', u'is_timezone_support_enabled': False, u'schema_hash': u'450f452f8addcd23370a8a90f8156c4a'}]


Trying to connect from Maya Script Editor...
############# DATA ##########
[{"action": "query_server_information"}]
############# RESULT ##########
[{u'storage_scenario': {u'data': {}, u'scenario': u'ftrack.automatic'}, u'version': u'4.1.5.4750', u'is_timezone_support_enabled': False, u'schema_hash': u'450f452f8addcd23370a8a90f8156c4a'}]

Note that DATA logs the data being POSTed to the api server and RESULT logs the result returned from that POST.
From that log I can't see any difference between the 3 different contexts from which I try to connect to the API.

 

I think the problem has something to do with the execution from within the pyblish plugin but I don't understand why the error just appeared basically out of nowhere.

I'm afraid that this is also something that is quite hard to reproduce for you?!

Thanks for your answer!
 

[tweak-wtf]

Update:

I just wrapped my connection call in try/catch block and printed the stacktrace... maybe that is also helping?!

Call to connect to API:

session = None
try:
  session = ftrack_api.Session(
    server_url = FTRACK_SERVER,
    api_key    = FTRACK_API_KEY,
    api_user   = getpass.getuser(),
  )
except Exception as e:
  self.log.debug("Session: {}".format(session))
  self.log.debug(traceback.format_exc(e))

Stacktrace:

// pyblish.CollectFTrackInfo : Traceback (most recent call last):
  File "<string>", line 35, in process
  File "/prod/softprod/libs/ftrack_api/session.py", line 224, in __init__
    self._server_information = self._fetch_server_information()
  File "/prod/softprod/libs/ftrack_api/session.py", line 1317, in _fetch_server_information
    result = self._call([{'action': 'query_server_information'}])
  File "/prod/softprod/libs/ftrack_api/session.py", line 1619, in _call
    raise ftrack_api.exception.ServerError(error_message)
ServerError: <unprintable ServerError object>
 // 

 

[Lorenzo Angeli]

Hi @tweak-wtf , thanks for reporting back , and good idea to raise the overall logging level !
Sadly though, I cannot see anything in the errors that would help pin point the root cause.

As the error seems to be happening from within the plugin only, and not from a plain shell or plain maya, I'd suggest have the pyblishs developers involved. 
If you get any further information coming out from them, please feel free to report here so we can cross examine the results.
As last thing , could you please check what interpreter pyblish is using adding at the beginning of your script: 
 

import sys
print sys.executable

In the meanwhile we'll keep looking on potential causes on our side.

L.

[tweak-wtf]

Hey @Lorenzo Angeli

the output of sys.executable is: /prod/softprod/apps/maya/2018/linux/bin/maya.bin

I've also printed the used python version if that's of any any use: 2.7.11 (default, Dec 21 2015, 14:39:44) [GCC 4.4.7 20120313 (Red Hat 4.4.7-11)

 

I have already shortly touched base with the pyblish developers on gitter. They pointed out to me that the actual key gets quoted. So if you have a look at my first stacktrace in this thread you see the KeyError is on '"storage_scenario"' but i guess it should rather be 'storage_scenario'.
So that KeyError is actually raised when I want to print the ServerError which is handled in the __str__ method of exception.py.

I think that is also the reason why I get ServerError: <unprintable ServerError object> in my last stacktrace.

I don't know for sure but I think if I would manage to print the actual ServerError that would already be really helpful.

[Lorenzo Angeli]

Hi @tweak-wtf sadly there's no easy way for us to replicate this issue.
We'll be looking though, to improve the error logging in the api to present a more complete report.

Let us know if you have any progress on this.
Cheers.
L.

[Lorenzo Angeli]

I'd like to report here , for other users which might find similar issues, the root cause which has been resolved through the internal ticketing system.

Here the full reply from our developer:
 

Quote

The key error is because the JSON blob with which the server responds is used as the error message when the ServerError is raised. When displaying that error, we call the format() method on the error message string. Since it's a JSON blob, the braces are interpreted as replacement fields, so format() expects keys to have a key-value pair for the first word inside the first braces in the server response, which is "storage_scenario". This is erroneous.

we are looking now on how to properly fix this for an upcoming api release.