Fatal Error: Credentials under UI7 1.7.719

I went back and looked and realized that I when I created a new credential key after changing accounts I had not deleted the old key. Once I removed the old key in the Google credentials then suddenly GCal worked!

Strangely… today I’m getting an error and a new one at that… I haven’t changed anything since yesterday so I’m truly puzzled. Here’s the error.

Fatal error - access token

For efficiency and to avoid having tokens stored on the file system - the plugin stores some of this information in memory. It’s possible that it got confused - so try a reboot and let me know. If it’s still got an errorthen visit the debug section of the main post and test with the credentials file and calendar id (carefully following the instructions) that are in the debug section.

It should work.

Next go back and change your credentials file name, upload your credentials file and then set the calendar id (i.e. the same sequence as described in the debug section)

If there is still an error then it will be in the credentials file, calendar id or the sharing settings of the calendar itself. If that’s the case - I’d recommend carefully going through the service account setup steps again.

I tried rebooting and the message has changed again. Now it says:

Waiting for another process claim…

Starting Up

Let me know if that means anymore to you otherwise I’ll go ahead and redo it all one more time.

In theory - that cannot happen after a reboot with the latest versions. For one reason at least … there is no “Starting Up” message.

Did it say anything at the end of “Waiting for another process claim” ? It’s possible that the message was truncated. I’ve made the message smaller and included a version identifier in the variables so we can make sure you have the latest.

Please apply the following and lets take another crack at this.

Go to Apps → Develop Apps → Luup files. Make sure that “restart Luup after upload is checked”
Upload the attached file and when completed press “Done”. Luup will restart.

Press F5 - you will often need to do this to get the UI to update.

Goto the Advanced → Variables tab for the plugin. Look for the gc_Version value (likely at the bottom). Confirm that the value is V 1.7a4. This is the version for this patch.

Is it working ? If not what does the message say ?

If it’s not working – go through the test / validation steps under the debugging section on the first post.

EDIT: Attachment Removed

Did all this and where it used to say at the bottom of the tile “Start Up” (sorry said Starting Up last time but no 'ing) it now alternates between saying:

“Calendar is Set” and “Fatal error - access token”

gc_version is “V 1.7a4”

I’ll take a look at the debug stuff and let you know what I find.

log file

50 01/27/16 22:39:30.101 luup_log:107: GCal3 V 1.7a4:local function: GCalMain <0x2f469680>
06 01/27/16 22:39:30.101 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: Fatal error - access token now: Start up … #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f469680>
06 01/27/16 22:39:30.102 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: 1 now: . #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f469680>
06 01/27/16 22:39:30.102 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: Start up … now: The CalendarID is set #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f469680>
06 01/27/16 22:39:30.103 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: . #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2f469680>
50 01/27/16 22:39:30.103 luup_log:107: GCal3 V 1.7a4: ************** ARMED STATUS : 1 ***************** <0x2f469680>

50 01/27/16 22:39:30.154 luup_log:107: GCal3 V 1.7a4:local function: checkGCal <0x2f469680>
06 01/27/16 22:39:30.154 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: Set up variables #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f469680>
50 01/27/16 22:39:30.155 luup_log:107: GCal3 V 1.7a4:local function: setupVariables <0x2f469680>
06 01/27/16 22:39:30.155 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: The CalendarID is set now: #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f469680>
06 01/27/16 22:39:30.155 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: Set up variables now: . #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f469680>
50 01/27/16 22:39:30.156 luup_log:107: GCal3 V 1.7a4:local function: makeBoolean <0x2f469680>
06 01/27/16 22:39:30.157 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_exactKeyword was: true now: true #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2f469680>
50 01/27/16 22:39:30.157 luup_log:107: GCal3 V 1.7a4:local function: makeBoolean <0x2f469680>
06 01/27/16 22:39:30.157 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_ignoreKeyword was: false now: false #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2f469680>
50 01/27/16 22:39:30.158 luup_log:107: GCal3 V 1.7a4:local function: makeBoolean <0x2f469680>
06 01/27/16 22:39:30.158 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_triggerNoKeyword was: false now: false #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2f469680>
50 01/27/16 22:39:30.158 luup_log:107: GCal3 V 1.7a4:local function: makeBoolean <0x2f469680>
06 01/27/16 22:39:30.159 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_ignoreAllDayEvent was: false now: false #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2f469680>
50 01/27/16 22:39:30.159 luup_log:107: GCal3 V 1.7a4:local function: makeBoolean <0x2f469680>
06 01/27/16 22:39:30.159 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_retrip was: true now: true #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2f469680>
50 01/27/16 22:39:30.160 luup_log:107: GCal3 V 1.7a4:local function: parseCalendar <0x2f469680>
50 01/27/16 22:39:30.160 luup_log:107: GCal3 V 1.7a4:Input: rutledgehouse43@gmail.com <0x2f469680>
50 01/27/16 22:39:30.160 luup_log:107: GCal3 V 1.7a4:After recoding: rutledgehouse43@gmail.com <0x2f469680>
50 01/27/16 22:39:30.163 luup_log:107: GCal3 V 1.7a4:Eliminate anything after %40gmail.com <0x2f469680>
50 01/27/16 22:39:30.163 luup_log:107: GCal3 V 1.7a4:rutledgehouse43@gmail.com <0x2f469680>
50 01/27/16 22:39:30.164 luup_log:107: GCal3 V 1.7a4: – ?src= <0x2f469680>
50 01/27/16 22:39:30.164 luup_log:107: GCal3 V 1.7a4:rutledgehouse43%40gmail.com <0x2f469680>
50 01/27/16 22:39:30.165 luup_log:107: GCal3 V 1.7a4: – &src= <0x2f469680>
50 01/27/16 22:39:30.165 luup_log:107: GCal3 V 1.7a4:rutledgehouse43%40gmail.com <0x2f469680>
06 01/27/16 22:39:30.165 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_CalendarID was: rutledgehouse43@gmail.com now: rutledgehouse43@gmail.com #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2f469680>
50 01/27/16 22:39:30.166 luup_log:107: GCal3 V 1.7a4:Calendar ID is: rutledgehouse43%40gmail.com <0x2f469680>
50 01/27/16 22:39:30.166 luup_log:107: GCal3 V 1.7a4:local function: makejson <0x2f469680>
06 01/27/16 22:39:30.166 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_jsonEvents was: [] now: [] #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2f469680>
50 01/27/16 22:39:30.167 luup_log:107: GCal3 V 1.7a4:local function: makejson <0x2f469680>
06 01/27/16 22:39:30.167 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_jsonActiveEvents was: [] now: [] #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2f469680>
06 01/27/16 22:39:30.168 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_ActiveEvents was: now: #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2f469680>
06 01/27/16 22:39:30.168 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_Version was: V 1.7a4 now: V 1.7a4 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2f469680>
06 01/27/16 22:39:30.169 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: Variable setup complete #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f469680>
50 01/27/16 22:39:30.169 luup_log:107: GCal3 V 1.7a4:local function: getStartMinMax <0x2f469680>
50 01/27/16 22:39:30.171 luup_log:107: GCal3 V 1.7a4:StartMin is 2016-01-27T05:00:00Z StartMax is 2016-01-29T03:40:00Z <0x2f469680>
50 01/27/16 22:39:30.172 luup_log:107: GCal3 V 1.7a4:End of day is 2016-01-27T23:59:59 <0x2f469680>
50 01/27/16 22:39:30.172 luup_log:107: GCal3 V 1.7a4:local function: requestCalendar <0x2f469680>
50 01/27/16 22:39:30.172 luup_log:107: GCal3 V 1.7a4:local function: get_access_token <0x2f469680>

50 01/27/16 22:39:30.389 luup_log:107: GCal3 V 1.7a4:Token Info request status: HTTP/1.1 400 Bad Request <0x2f469680>
50 01/27/16 22:39:30.389 luup_log:107: GCal3 V 1.7a4:Getting a new token <0x2f469680>
50 01/27/16 22:39:30.390 luup_log:107: GCal3 V 1.7a4:local function: os_command <0x2f469680>

50 01/27/16 22:39:30.436 luup_log:107: GCal3 V 1.7a4:local function: os_command <0x2f469680>

50 01/27/16 22:39:30.480 luup_log:107: GCal3 V 1.7a4:local function: os_command <0x2f469680>

50 01/27/16 22:39:30.786 luup_log:107: GCal3 V 1.7a4:local function: os_command <0x2f469680>

50 01/27/16 22:39:30.954 luup_log:107: GCal3 V 1.7a4:The token request did not provide an access token <0x2f469680>
06 01/27/16 22:39:30.955 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: now: Fatal error - access token #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f469680>
06 01/27/16 22:39:30.955 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: Variable setup complete now: . #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f469680>
50 01/27/16 22:39:30.956 luup_log:107: GCal3 V 1.7a4:Fatal error trying to get access token <0x2f469680>
06 01/27/16 22:39:30.956 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: 2 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f469680>
06 01/27/16 22:39:30.957 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_jsonEvents was: [] now: [] #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2f469680>
06 01/27/16 22:39:30.957 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_jsonActiveEvents was: [] now: [] #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2f469680>
06 01/27/16 22:39:30.957 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_ActiveEvents was: now: #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:1 <0x2f469680>
50 01/27/16 22:39:30.958 luup_log:107: GCal3 V 1.7a4:local function: setNextTimeCheck <0x2f469680>
50 01/27/16 22:39:30.958 luup_log:107: GCal3 V 1.7a4:nextCheckTime: 1453952430 <0x2f469680>
06 01/27/16 22:39:30.959 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_lastCheck was: 2016-01-27 at 22:38:30 now: 2016-01-27 at 22:39:30 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f469680>
06 01/27/16 22:39:30.961 Device_Variable::m_szValue_set device: 107 service: urn:srs-com:serviceId:GCalIII variable: gc_nextCheck was: 2016-01-27 at 22:39:30 now: 2016-01-27 at 22:40:30 #hooks: 0 upnp: 0 v:(nil)/NONE duplicate:0 <0x2f469680>
50 01/27/16 22:39:30.962 luup_log:107: GCal3 V 1.7a4:Next check will be in 60 sec on 2016-01-27 at 22:40:30 <0x2f469680>


I added a separate instance of GCal and configured it as you describe and it successfully returns the test event. Not sure what changed that caused mine to stop working since yesterday.

Ok – the fact that usingthe test calendar and credentials confirms that the plugin is working correctly.

So problem lies in the credentials file:

“GCal3 V 1.7a4:The token request did not provide an access token”

This means that google does not recognize the credentials file and is not returning a token that can be used to query the calendar.

You need to go through the process of creating a credentials file being careful to follow the steps exactly and then set the sharing permissions on the calendar for this new credentials file. Please follow the steps posted in the instructions in the first post of the main thread - from start to finish. Google did a pretty good job on their security :frowning:

Reset it all again and it’s working again. Not sure why it changed the other day but hopefully all is permanently well now. Also thanks for pointing me to InfoViewer. Since I’m remote from my Vera most of the time it’s great to have a way to get to the logs now!

Hmm - Infoviewer … are you using UI5 ? InfoViewer worked remotely for UI5 but last time I looked it was not working remotely with UI7 ??