Fatal Error: Credentials under UI7 1.7.719

I’m having some problems connecting to the Google Calendar with my Vera Lite, running UI7, firmware 1.7.719.

I have enabled the Calendar API and generated the .json file as an ‘other’ OAuth type, then installed the plugin (1.4 from the Vera Install Apps section, uploaded the file and pasted in the full embedded URL for the calendar. (I’ve also tried with the direct URL, with and without converting the & to %26).

Once this is done, under the control tab it says Variable setup complete.

However with or without a reboot I get a Fatal Error: Credentials when it tries to check the events.

If I SSH into the box, I can see it has created the /etc/cmh-ludl/GCal3 folder which contains D_GCal3.json, GCal3.json and GCal3.sem.

The calendar tab won’t display the calendar due to a DNS error, it’s possibly missing a /?
https://calendar.google.com%26showprint%3D0%26showtabs… is the URL it’s trying to use.

The gc_CalendarID is still set to https://calendar.google.com in the variables.

I don’t see anything in the logs that suggest exactly where the issue lies.

I’m betting I’ve missed something fundamental, but I can’t spot what it is! I’ve tried uninstalling and re-installing the plugin, but to no avail.

I can grab you whatever data you need.

Thanks in advance!
Modify message

I’m traveling and cannot offer direct assistance. My guess is that you have not created the credentials file correctly. As a result some of the files in the …/ GCal3 directory are wrong The credentials file needs to be for a service account. Take a look at the instructions on the first post of the main thread. They are a little dated from a UI perspective but otherwise accurate.

Setting gc_debug to 3 will give maximum debug messages.

Sorry, I didn’t get a chance to update this sooner.

I recreated the service account again, and it cleared the credentials error, however I’m still not able to view the calendar on the calendar tab, and it’s not picking up the events.

I’ll turn the logging up and dig in, see what’s going on.

No problem. You need to be logged into your google account in the current browser session for the calendar tab to show up. One day I will figure out how to pass the credentials within the calendar tab but until then … ???

Looks like either I’m being an utter muppet, or it’s not happy with my Calendar URL.

I used the iframe URL as suggested, however the logs are showing it gets a 404 error when it tries to connect.

If I extract the URL from the link and paste it into the browser it works fine. The calendar link in vera still shows a DNS error.

Tried under both Firefox and Chrome just in case.

gc_CalendarID is set to https://calendar.google.com when I look.

I’ve tried the iframe link both with the &, and the %26.

In the log, these seem the most relevant entries:

06      12/03/15 20:20:20.133   Device_Variable::m_szValue_set device: 34 service: urn:srs-com:serviceId:GCalIII variable: gc_CalendarID was:  now: https://calendar.google.com #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2dce4680>

10      12/03/15 20:20:20.134   UserData::m_iDataVersion_Variables_incr gc_CalendarID user data 196581001 variables 196585201 <0x2dce4680>

06      12/03/15 20:21:20.822   Device_Variable::m_szValue_set device: 34 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: Accessing Calendar now: Http error code: 404 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2dce4680>

Thanks for your help so far!

are you pasting the entire iframe link including the <iframe … e.g.

Note that the link details cannot be input into the gc_CalendarID variable on the advanced tab (some people do this and have similar problems). It must be input using the Control Tab and the “set” button. This is because the plugin parses out the bits that it needs.

The resultant value for gc_CalendarID that you describe is clearly wrong - which suggests that the parser failed. This can be because the wrong format was input, google changed their format and the parser no longer recognizes it or there is a bug in the parser.

If the above does not help - I’ll put some debug messages into the parser routine (have not needed them up till now) and have you retest.

Yep, both for the main calendar for that account and the calendar I’m trying to use:

<iframe src="https://calendar.google.com/calendar/embed?src={USER}%40gmail.com&ctz=America/Phoenix" style="border: 0" width="800" height="600" frameborder="0" scrolling="no"></iframe>

<iframe src="https://calendar.google.com/calendar/embed?src={GUID}%40group.calendar.google.com&ctz=America/Phoenix" style="border: 0" width="800" height="600" frameborder="0" scrolling="no"></iframe>

<iframe src="https://calendar.google.com/calendar/embed?src={GUID}%40gmail.com&ctz=America/Phoenix" style="border: 0" width="800" height="600" frameborder="0" scrolling="no"></iframe>

I think I have it fixed - I’d been a little lazy and a little too optimistic about some google calendar format variations …

Try the update file here:

http://forum.micasaverde.com/index.php/topic,26692.msg259438.html#msg259438

Thank you for pointing this out and providing the failing examples - that really helped.

Remember to F5 after using ‘set’ before looking at the result of gc_CalendarID in the advanced tab :-). It’s spooky when things that should have changed do not …

Thank you for taking a look!

As soon as I get a chance I’ll get that update done, it’s currently 1.4 so we’re good there.

I’ll let you know how I get on.

Hello,

I uploaded the GCal3.lua file from the other thread, but the version number still says 1.4, even after a reboot.

I did however change the urn and the calendar url to use www. and the calendar tab now works, although it still gives a Access or Calendar error.

I’ve probably missed something in the upgrade process, but this initial test at least shows it was the DNS name that was affecting it!

I’ll take a closer look at the weekend, I’ve probably just missed a step along the way.

Did you use the vera UI to upload ? As opposed to something like WINSCP ? The vera upload (from memory) creates a lzo file and that’s what triggers the internal upgrade of the plugin file.

I’d also reboot to be doubly certain (not usually required but …)

I assume you are saying “1.4” because that’s what shows up in the log file (the log file is definitive)? The “My apps” version number will only show the version from your last install / upgrade from the apps store.

I’ll check the logs tonight, but yes, I took the MyApps number, so it may well have worked.

I did upload it with the Vera GUI so I expect it did upgrade. Is there a way to check the installed version from the command line?

As far as I know the installed version number is set by the vera marketplace. I’m not aware of any way to programmatically set the version number. I use a variable that gets included in log messages - so checking the logs is the only way I can suggest.

Hello,

I’ve had a look through the logs, the Calendar tab works, copying the variable to the browser and running it works, but the log says 404 when it tries to get events. It is running 15b though!

Here’s the last run in the logs. {} changed to protect the innocent!

06	12/14/15 17:41:13.102	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: Access or Calendar Error now: Start up ... #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/14/15 17:41:13.102	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: 307 now: . #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/14/15 17:41:13.103	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: Start up ... now: The CalendarID is set #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/14/15 17:41:13.104	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: . #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/14/15 17:41:13.138	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: Set up variables #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/14/15 17:41:13.139	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: The CalendarID is set now:  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/14/15 17:41:13.140	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: Set up variables now: . #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/14/15 17:41:13.141	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_exactKeyword was: true now: true #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/14/15 17:41:13.142	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_ignoreKeyword was: false now: false #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/14/15 17:41:13.142	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_triggerNoKeyword was: false now: false #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/14/15 17:41:13.143	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_ignoreAllDayEvent was: false now: false #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/14/15 17:41:13.144	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_retrip was: true now: true #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/14/15 17:41:13.144	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_CalendarID was: https://calendar.google.com/calendar/embed?src={GUID}0%40group.calendar.google.com now:  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/14/15 17:41:13.154	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_CalendarID was:  now: https://calendar.google.com/calendar/embed?src={GUID}0%40group.calendar.google.com #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/14/15 17:41:13.155	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_jsonEvents was: [] now: [] #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/14/15 17:41:13.156	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_jsonActiveEvents was: [] now: [] #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/14/15 17:41:13.156	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_ActiveEvents was:  now:  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/14/15 17:41:13.157	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: Variable setup complete #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
04	12/14/15 17:41:13.249	 <0x2b4ec680>
06	12/14/15 17:41:13.250	Device_Variable::m_szValue_set device: 4 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: LastPollSuccess was: 1450139953 now: 1450140073 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <0x2b4ec680>
06	12/14/15 17:41:13.251	Device_Variable::m_szValue_set device: 4 service: urn:micasaverde-com:serviceId:ZWaveNetwork1 variable: ConsecutivePollFails was: 0 now: 0 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <0x2b4ec680>
06	12/14/15 17:41:13.537	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was:  now: Accessing Calendar #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/14/15 17:41:13.538	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: Variable setup complete now: . #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/14/15 17:41:14.001	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: Accessing Calendar now: Http error code: 404 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/14/15 17:41:14.001	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: . #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/14/15 17:41:14.002	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: Http error code: 404 now: Access or Calendar Error #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/14/15 17:41:14.003	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: 308 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/14/15 17:41:14.003	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_jsonEvents was: [] now: [] #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/14/15 17:41:14.004	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_jsonActiveEvents was: [] now: [] #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/14/15 17:41:14.004	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_ActiveEvents was:  now:  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/14/15 17:41:14.006	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_lastCheck was: 2015-12-14 at 17:41:04 now: 2015-12-14 at 17:41:13 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/14/15 17:41:14.009	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_nextCheck was: 2015-12-14 at 17:42:04 now: 2015-12-14 at 17:42:13 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
50	12/14/15 17:41:14.009	luup_log:35: GCal3 V 1.5b:Next check will be in 60 sec on 2015-12-14 at 17:42:13 <{DEV_ID}>

Please set gc_debug = 3. That way we will see the debug messages and can begin to make sense of what’s happening.

Duly set, I think this is all of one run:

06	12/15/15 21:43:53.118	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: Access or Calendar Error now: GCal3.sem #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/15/15 21:43:53.119	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: 544 now: Could not Open #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
50	12/15/15 21:43:53.139	luup_log:35: GCal3 V 1.5b:Device 35 claimed semaphore <{DEV_ID}>
06	12/15/15 21:43:53.140	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: GCal3.sem now:  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/15/15 21:43:53.141	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: Could not Open now: . #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/15/15 21:43:53.142	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_exactKeyword was: true now: true #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/15/15 21:43:53.142	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_ignoreKeyword was: false now: false #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/15/15 21:43:53.143	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_triggerNoKeyword was: false now: false #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/15/15 21:43:53.144	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_ignoreAllDayEvent was: false now: false #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/15/15 21:43:53.145	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_retrip was: true now: true #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/15/15 21:43:53.146	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_CalendarID was: https://calendar.google.com/calendar/embed?src={GUID}%40group.calendar.google.com now:  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/15/15 21:43:53.152	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_CalendarID was:  now: https://calendar.google.com/calendar/embed?src={GUID}%40group.calendar.google.com #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/15/15 21:43:53.153	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_jsonEvents was: [] now: [] #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/15/15 21:43:53.154	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_jsonActiveEvents was: [] now: [] #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/15/15 21:43:53.155	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_ActiveEvents was:  now:  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
50	12/15/15 21:43:53.156	luup_log:35: GCal3 V 1.5b:GCal3 V 1.5b:Variables initialized ... <{DEV_ID}>
50	12/15/15 21:43:53.174	luup_log:35: GCal3 V 1.5b:Command /bin/ls /usr/lib/lua/json.lua returned 0 <{DEV_ID}>
50	12/15/15 21:43:53.232	luup_log:35: GCal3 V 1.5b:Existing openssl version is: 1.0.0d-1 <{DEV_ID}>
50	12/15/15 21:43:53.246	luup_log:35: GCal3 V 1.5b:local function: checkforcredentials <{DEV_ID}>
50	12/15/15 21:43:53.264	luup_log:35: GCal3 V 1.5b:Command /bin/ls /etc/cmh-ludl/GCal3.json.lzo returned 256 <{DEV_ID}>
50	12/15/15 21:43:53.282	luup_log:35: GCal3 V 1.5b:Command /bin/ls /etc/cmh-ludl/GCal3/GCal3.json returned 0 <{DEV_ID}>
50	12/15/15 21:43:53.283	luup_log:35: GCal3 V 1.5b:local function: readfromFile <{DEV_ID}>
50	12/15/15 21:43:53.300	luup_log:35: GCal3 V 1.5b:Command /bin/ls /etc/cmh-ludl/GCal3/GCal3.json returned 0 <{DEV_ID}>
50	12/15/15 21:43:53.383	luup_log:35: GCal3 V 1.5b:local function: getTimezone <{DEV_ID}>
50	12/15/15 21:43:53.384	luup_log:35: GCal3 V 1.5b:GCal3 V 1.5b:Timezone is -7 hrs and -0 min <{DEV_ID}>
50	12/15/15 21:43:53.385	luup_log:35: GCal3 V 1.5b:GCal3 V 1.5b:Running Plugin ... <{DEV_ID}>
06	12/15/15 21:43:53.385	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was:  now: Successfully Initialized #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/15/15 21:43:53.386	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: . #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
50	12/15/15 21:43:53.387	luup_log:35: GCal3 V 1.5b:local function: writetoFile <{DEV_ID}>
50	12/15/15 21:43:53.389	luup_log:35: GCal3 V 1.5b:Device 35 released the semaphore - reason: initialization complete <{DEV_ID}>
50	12/15/15 21:43:54.100	luup_log:35: GCal3 V 1.5b:local function: GCalMain <{DEV_ID}>
06	12/15/15 21:43:54.101	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: Successfully Initialized now: Start up ... #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/15/15 21:43:54.102	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: . #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/15/15 21:43:54.102	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: Start up ... now: The CalendarID is set #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/15/15 21:43:54.103	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: . #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
50	12/15/15 21:43:54.104	luup_log:35: GCal3 V 1.5b: ************** ARMED STATUS : 1 ***************** <{DEV_ID}>
50	12/15/15 21:43:54.375	luup_log:35: GCal3 V 1.5b:local function:  checkGCal <{DEV_ID}>
06	12/15/15 21:43:54.376	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: Set up variables #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
50	12/15/15 21:43:54.377	luup_log:35: GCal3 V 1.5b:local function: setupVariables <{DEV_ID}>
06	12/15/15 21:43:54.421	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: The CalendarID is set now:  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/15/15 21:43:54.421	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: Set up variables now: . #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
50	12/15/15 21:43:54.422	luup_log:35: GCal3 V 1.5b:local function: makeBoolean <{DEV_ID}>
06	12/15/15 21:43:54.423	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_exactKeyword was: true now: true #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
50	12/15/15 21:43:54.424	luup_log:35: GCal3 V 1.5b:local function: makeBoolean <{DEV_ID}>
06	12/15/15 21:43:54.425	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_ignoreKeyword was: false now: false #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
50	12/15/15 21:43:54.425	luup_log:35: GCal3 V 1.5b:local function: makeBoolean <{DEV_ID}>
06	12/15/15 21:43:54.426	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_triggerNoKeyword was: false now: false #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
50	12/15/15 21:43:54.427	luup_log:35: GCal3 V 1.5b:local function: makeBoolean <{DEV_ID}>
06	12/15/15 21:43:54.427	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_ignoreAllDayEvent was: false now: false #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
50	12/15/15 21:43:54.444	luup_log:35: GCal3 V 1.5b:local function: makeBoolean <{DEV_ID}>
06	12/15/15 21:43:54.444	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_retrip was: true now: true #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
50	12/15/15 21:43:54.445	luup_log:35: GCal3 V 1.5b:local function: parseCalendar <{DEV_ID}>
50	12/15/15 21:43:54.446	luup_log:35: GCal3 V 1.5b:As Input <{DEV_ID}>
50	12/15/15 21:43:54.446	luup_log:35: GCal3 V 1.5b:https://calendar.google.com/calendar/embed?src={GUID}%40group.calendar.google.com <{DEV_ID}>
06	12/15/15 21:43:54.447	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_CalendarID was: https://calendar.google.com/calendar/embed?src={GUID}%40group.calendar.google.com now:  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
50	12/15/15 21:43:54.526	luup_log:35: GCal3 V 1.5b:After recoding <{DEV_ID}>
50	12/15/15 21:43:54.527	luup_log:35: GCal3 V 1.5b:https://calendar.google.com/calendar/embed?src={GUID}%40group.calendar.google.com <{DEV_ID}>
50	12/15/15 21:43:54.611	luup_log:35: GCal3 V 1.5b:Eliminate anything after %40group.calendar.google.com <{DEV_ID}>
50	12/15/15 21:43:54.611	luup_log:35: GCal3 V 1.5b:https://calendar.google.com/calendar/embed?src={GUID}%40group.calendar.google.com <{DEV_ID}>
50	12/15/15 21:43:54.613	luup_log:35: GCal3 V 1.5b: -- ?src= <{DEV_ID}>
50	12/15/15 21:43:54.614	luup_log:35: GCal3 V 1.5b:{GUID}%40group.calendar.google.com <{DEV_ID}>
50	12/15/15 21:43:54.616	luup_log:35: GCal3 V 1.5b: -- &src= <{DEV_ID}>
50	12/15/15 21:43:54.616	luup_log:35: GCal3 V 1.5b:{GUID}%40group.calendar.google.com <{DEV_ID}>
06	12/15/15 21:43:54.617	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_CalendarID was:  now: https://calendar.google.com/calendar/embed?src={GUID}%40group.calendar.google.com #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
50	12/15/15 21:43:54.628	luup_log:35: GCal3 V 1.5b:Calendar ID is: {GUID}%40group.calendar.google.com <{DEV_ID}>
50	12/15/15 21:43:54.629	luup_log:35: GCal3 V 1.5b:local function: makejson <{DEV_ID}>
06	12/15/15 21:43:54.629	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_jsonEvents was: [] now: [] #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
50	12/15/15 21:43:54.630	luup_log:35: GCal3 V 1.5b:local function: makejson <{DEV_ID}>
06	12/15/15 21:43:54.631	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_jsonActiveEvents was: [] now: [] #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/15/15 21:43:54.631	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_ActiveEvents was:  now:  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/15/15 21:43:54.632	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: Variable setup complete #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
50	12/15/15 21:43:54.633	luup_log:35: GCal3 V 1.5b:local function: getStartMinMax <{DEV_ID}>
50	12/15/15 21:43:54.636	luup_log:35: GCal3 V 1.5b:StartMin is 2015-12-15T07:00:00Z StartMax is 2015-12-17T04:44:00Z <{DEV_ID}>
50	12/15/15 21:43:54.636	luup_log:35: GCal3 V 1.5b:End of day is 2015-12-15T23:59:59 <{DEV_ID}>
50	12/15/15 21:43:54.637	luup_log:35: GCal3 V 1.5b:local function: requestCalendar <{DEV_ID}>
50	12/15/15 21:43:54.657	luup_log:35: GCal3 V 1.5b:local function: get_access_token <{DEV_ID}>
50	12/15/15 21:43:55.046	luup_log:35: GCal3 V 1.5b:Token Info request status: HTTP/1.1 400 Bad Request <{DEV_ID}>
50	12/15/15 21:43:55.046	luup_log:35: GCal3 V 1.5b:Getting a new token <{DEV_ID}>
50	12/15/15 21:43:55.047	luup_log:35: GCal3 V 1.5b:local function: os_command <{DEV_ID}>
50	12/15/15 21:43:55.383	luup_log:35: GCal3 V 1.5b:local function: os_command <{DEV_ID}>
50	12/15/15 21:43:55.423	luup_log:35: GCal3 V 1.5b:local function: os_command <{DEV_ID}>
50	12/15/15 21:43:55.729	luup_log:35: GCal3 V 1.5b:local function: os_command <{DEV_ID}>
50	12/15/15 21:43:56.067	luup_log:35: GCal3 V 1.5b:Got new token <{DEV_ID}>
50	12/15/15 21:43:56.075	luup_log:35: GCal3 V 1.5b:Checking google calendar <{DEV_ID}>
06	12/15/15 21:43:56.076	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was:  now: Accessing Calendar #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/15/15 21:43:56.077	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: Variable setup complete now: . #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
50	12/15/15 21:43:56.078	luup_log:35: GCal3 V 1.5b:Requested url: https://www.googleapis.com/calendar/v3/calendars/{GUID}%40group.calendar.google.com/events?access_token=ya29.{TOKEN}-Vuyl1Dg&timeZone=utc&singleEvents=true&orderBy=startTime&timeMax=2015-12-17T04:44:00Z&timeMin=2015-12-15T07:00:00Z&fields=items(description%2Cend%2Cstart%2Csummary) <{DEV_ID}>
01	12/15/15 21:43:56.101	LuaInterface::CallFunction_Timer-5 function StartupCheck failed [string "module("L_VeraAlert", package.seeall)..."]:1137: attempt to concatenate global 'lul_device' (a nil value) <0x2d276680>
50	12/15/15 21:43:56.601	luup_log:35: GCal3 V 1.5b:Http error code: 404 <{DEV_ID}>
06	12/15/15 21:43:56.602	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: Accessing Calendar now: Http error code: 404 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/15/15 21:43:56.603	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: . #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/15/15 21:43:56.603	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEvent was: Http error code: 404 now: Access or Calendar Error #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/15/15 21:43:56.604	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_NextEventTime was: . now: 1 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/15/15 21:43:56.605	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_jsonEvents was: [] now: [] #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/15/15 21:43:56.606	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_jsonActiveEvents was: [] now: [] #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
06	12/15/15 21:43:56.606	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_ActiveEvents was:  now:  #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:1 <{DEV_ID}>
50	12/15/15 21:43:56.607	luup_log:35: GCal3 V 1.5b:local function: setNextTimeCheck <{DEV_ID}>
50	12/15/15 21:43:56.608	luup_log:35: GCal3 V 1.5b:nextCheckTime: 1450241096 <{DEV_ID}>
06	12/15/15 21:43:56.609	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_lastCheck was: 2015-12-15 at 21:42:03 now: 2015-12-15 at 21:43:56 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
06	12/15/15 21:43:56.612	Device_Variable::m_szValue_set device: 35 service: urn:srs-com:serviceId:GCalIII variable: gc_nextCheck was: 2015-12-15 at 21:43:03 now: 2015-12-15 at 21:44:56 #hooks: 0 upnp: 0 skip: 0 v:(nil)/NONE duplicate:0 <{DEV_ID}>
50	12/15/15 21:43:56.613	luup_log:35: GCal3 V 1.5b:Next check will be in 60 sec on 2015-12-15 at 21:44:56 <{DEV_ID}>

Everything looks normal - right up to:

50	12/15/15 21:43:56.078	luup_log:35: GCal3 V 1.5b:Requested url: https://www.googleapis.com/calendar/v3/calendars/{GUID}%40group.calendar.google.com/events?access_token=ya29.{TOKEN}-Vuyl1Dg&timeZone=utc&singleEvents=true&orderBy=startTime&timeMax=2015-12-17T04:44:00Z&timeMin=2015-12-15T07:00:00Z&fields=items(description%2Cend%2Cstart%2Csummary) <{DEV_ID}>
01	12/15/15 21:43:56.101	LuaInterface::CallFunction_Timer-5 function StartupCheck failed [string "module("L_VeraAlert", package.seeall)..."]:1137: attempt to concatenate global 'lul_device' (a nil value) <0x2d276680>
50	12/15/15 21:43:56.601	luup_log:35: GCal3 V 1.5b:Http error code: 404 <{DEV_ID}>

There is an error being thrown in L_VeraAlert – but that’s not our concern.

The 404 error could easily be a permissions problem.
Double check to make sure your calendar is set up per the document (see especially the last paragraph or so): Setting up a Google V3 API Service Account.pdf

Sorry, thought I’d updated this, but evidently not!

I redid the config from scratch, and it’s working fine now. I’m not sure if it was co-incidence, but the calDav api is now separate to the main calendar api, when I enabled it, it all started working, but that could have been coincidence!

Thanks for all your help.

I’ve also recently started having this problem on UI5.

I see status messages:
Checking
Variable Setup
and sometimes… Accessing

then I get:
Access or Calendar Error #
(where # is an ever increasing integer)

I’m running 1.6 and I’ve completely uninstalled, reinstalled, regenerated the .json file, reuploaded (via Vera UI), and removed and re-added the permission in Google Calendar and still the same thing. Unfortunately I’m remote so I can’t get to log files. I’ve tested uploading bogus .json files and I get a Credential Error so it is apparently seeing the file I’ve uploaded because I don’t see that when I upload a valid file. The calendar view successfully shows the calendar as well.

Any ideas?

What it means is that there was no valid response being returned by the call to the calendar (so it retries every minute). This can be due to a number of issues - there will be an error message before you get that message - but its being overwritten.

Here is a patch file that might make it easier to spot the real error. I made a change (commented out a line) to stop the message “Access or Calendar Error” so we can better see the prior error. The counter will still count up.

Without a log file the error messages only get us in the ballpark.

EDIT: removed patched version