6.0.0-beta1
7/4/25

[#14177] ActiveSync SQL error
Summary ActiveSync SQL error
Queue Synchronization
Queue Version FRAMEWORK_5_2
Type Bug
State Not Reproducible
Priority 2. Medium
Owners mrubinsk (at) horde (dot) org
Requester o+horde (at) immerda (dot) ch
Created 12/03/2015 (3501 days ago)
Due
Updated 12/25/2015 (3479 days ago)
Assigned 12/03/2015 (3501 days ago)
Resolved 12/25/2015 (3479 days ago)
Github Issue Link
Github Pull Request
Milestone
Patch No

History
12/25/2015 09:21:47 PM Michael Rubinsky Comment #10
State ⇒ Not Reproducible
Reply to this comment
Well, you are going to need to figure out why the share_name isn't 
being captured in Horde_Share_Sql::_listAllShares(). Look at the code 
around line 324:

             if (!empty($data['share_name'])) {
                 $sharelist[$data['share_name']] = $this->_createObject($data);
             } else {
                 $sharelist[] = $this->_createObject($data);
             }

and start digging there.


12/25/2015 11:04:00 AM o+horde (at) immerda (dot) ch Comment #9 Reply to this comment
Those array values should be string values (share names) and not 
even integers. Look in your share table (probably 
kronolith_sharesng) and see if you can find any shares with a share 
name of 0 or 1 (or ANY integer value). My guess is those are old 
left over cruft.
I already checked this table, there is nothing obviously suspicious 
there. I tried:

SELECT * FROM "public"."kronolith_sharesng" WHERE 
char_length("share_name") < 10

and

CREATE OR REPLACE FUNCTION convert_to_integer(v_input text)
RETURNS INTEGER AS $$
DECLARE v_int_value INTEGER DEFAULT NULL; BEGIN
BEGIN
     v_int_value := v_input::INTEGER;
     EXCEPTION WHEN OTHERS THEN
         RETURN NULL;
     END;
RETURN v_int_value;
END;
$$ LANGUAGE plpgsql;
SELECT * FROM "public"."kronolith_sharesng" where 
convert_to_integer("share_name") is not null

none of those queries returned a single row
12/24/2015 04:31:15 PM Michael Rubinsky Comment #8 Reply to this comment

[Show Quoted Text - 24 lines]
Those array values should be string values (share names) and not even 
integers. Look in your share table (probably kronolith_sharesng) and 
see if you can find any shares with a share name of 0 or 1 (or ANY 
integer value). My guess is those are old left over cruft.
12/24/2015 03:31:00 PM o+horde (at) immerda (dot) ch Comment #7 Reply to this comment

[Show Quoted Text - 15 lines]
Yeah indeed it end with:

   [1451]=>
   int(0)
   [1452]=>
   int(1)

What should we do about them?
12/23/2015 08:20:57 PM Michael Rubinsky State ⇒ No Feedback
 
12/05/2015 07:14:44 PM Michael Rubinsky Comment #6 Reply to this comment
Additionally I found out that the last entry before the error occurs
is the query for the last share in "SELECT * FROM kronolith_sharesng
ORDER BY share_name ASC" (which according to the debug log seems to
be query used by horde-alarms to get the list of shares).
By this I wanted to say it seems that the error occurs *after* all 
shares from kronolith_sharesng have already been processed.
Using the admin phpshell in Horde, look to see what the following 
produces (using Kronolith's scope):

$kronolith_shares = $injector->getInstance('Kronolith_Shares');
var_dump(array_keys($kronolith_shares->listAllShares()));

See if there are any "empty-ish" values listed.
12/04/2015 09:40:04 AM o+horde (at) immerda (dot) ch Comment #5 Reply to this comment
I think the ActiveSync part is a red herring and its rather a 
kronolith issue. At least I see the same issue arise on our hosts 
which do not get any ActiveSync traffic at all.
After closer inspection I realized that they are in fact two separate 
issues. The SQL error is caused solely by horde-alarms and the 
activeSync error is a different one. They just looked related since 
the activeSync ping interval and the horde-alarms cronjob have a 
similar frequency.
12/03/2015 03:13:10 PM o+horde (at) immerda (dot) ch Comment #4 Reply to this comment
Additionally I found out that the last entry before the error occurs 
is the query for the last share in "SELECT * FROM kronolith_sharesng 
ORDER BY share_name ASC" (which according to the debug log seems to 
be query used by horde-alarms to get the list of shares).
By this I wanted to say it seems that the error occurs *after* all 
shares from kronolith_sharesng have already been processed.
12/03/2015 03:11:35 PM o+horde (at) immerda (dot) ch Comment #3 Reply to this comment
The SQL error is a side effect of the WBXML protocol error that is 
listed first in the trace.
I think the ActiveSync part is a red herring and its rather a 
kronolith issue. At least I see the same issue arise on our hosts 
which do not get any ActiveSync traffic at all.

I found out that every run of the horde-alarms cron job triggers the 
error too. Unfortunately even full debug level does not yield a better 
error.

Additionally I found out that the last entry before the error occurs 
is the query for the last share in "SELECT * FROM kronolith_sharesng 
ORDER BY share_name ASC" (which according to the debug log seems to be 
query used by horde-alarms to get the list of shares).

On the other hand the number of 'select .... from kronolith_events 
...' queries does not match the number of entries in 
kronolith_sharesng, but maybe that's ok, since there seem to be 
duplicate names with different flags (from the migration from old 
style per-user calendar entries, it seems).

Any other things I could try?

For reference the error with full debug on looks like this:

2015-12-03T15:33:31+01:00 DEBUG: HORDE [kronolith] SQL
         SELECT event_id, event_uid, event_description, event_location,
           event_private, event_status, event_attendees, event_title,
           event_recurcount, event_url, event_timezone, event_recurtype,
           event_recurenddate, event_recurinterval, event_recurdays, 
event_start,
           event_end, event_allday, event_alarm, event_alarm_methods,
           event_modified, event_exceptions, event_creator_id, event_resources,
           event_baseid, event_exceptionoriginaldate FROM 
kronolith_events WHERE
           calendar_id = 0 AND event_alarm > 0 AND ((event_end >= '2015-12-02
           23:00:00') OR (event_recurenddate >= '2015-12-02 23:00:00' AND
           event_recurtype <> 0)) [pid 31771 on line 233 of 
"pear/php/Horde/Db/Adapter/Pdo/Base.php"]
2015-12-03T15:33:31+01:00 ERR: HORDE [kronolith] SQL QUERY FAILED: 
SQLSTATE[42883]: Undefined function: 7 ERROR:  operator does not 
exist: character varying = integer
LINE 1: ...ginaldate FROM kronolith_events WHERE calendar_id = 0 AND ev...
                                                              ^
HINT:  No operator matches the given name and argument type(s). You 
might need to add explicit type casts.
         SELECT event_id, event_uid, event_description, event_location,
           event_private, event_status, event_attendees, event_title,
           event_recurcount, event_url, event_timezone, event_recurtype,
           event_recurenddate, event_recurinterval, event_recurdays, 
event_start,
           event_end, event_allday, event_alarm, event_alarm_methods,
           event_modified, event_exceptions, event_creator_id, event_resources,
           event_baseid, event_exceptionoriginaldate FROM 
kronolith_events WHERE
           calendar_id = 0 AND event_alarm > 0 AND ((event_end >= '2015-12-02
           23:00:00') OR (event_recurenddate >= '2015-12-02 23:00:00' AND
           event_recurtype <> 0)) [pid 31771 on line 234 of 
"pear/php/Horde/Db/Adapter/Pdo/Base.php"]
2015-12-03T15:33:31+01:00 DEBUG: HORDE [horde] SQL  (0.0095s)
         SELECT alarm_id, alarm_uid, alarm_start, alarm_end, alarm_methods,
           alarm_params, alarm_title, alarm_text, alarm_snooze, alarm_internal
           FROM horde_alarms WHERE alarm_dismissed = 0 AND 
((alarm_snooze IS NULL
           AND alarm_start <= '2015-12-03 14:33:19') OR alarm_snooze <=
           '2015-12-03 14:33:19') AND (alarm_end IS NULL OR alarm_end >=
           '2015-12-03 14:33:19') ORDER BY alarm_start, alarm_end [pid 
31771 on line 238 of "pear/php/Horde/Db/Adapter/Pdo/Base.php"]
2015-12-03T15:33:31+01:00 DEBUG: HORDE [horde] Max memory usage: 
37486592 bytes [pid 31771 on line 609 of "pear/php/Horde/Registry.php"]

12/03/2015 12:46:05 PM Michael Rubinsky Comment #2
Assigned to Michael Rubinsky
State ⇒ Feedback
Reply to this comment
The SQL error is a side effect of the WBXML protocol error that is 
listed first in the trace.

To further debug this issue, we need details of the Horde -> Device 
connection. It may also be beneficial to obtain a network capture.

To enable debugging, see instructions contained in the ActiveSync 
section of Horde's configuration. Also, see 
http://wiki.horde.org/ActiveSync for more details.

Debugging should not be enabled on a production server,   Attach/post 
only the portion of the log that directly deals with the problem 
reported (it may be simplest to clear the log file and then perform 
the event that causes the error).
12/03/2015 08:41:03 AM o+horde (at) immerda (dot) ch Comment #1
Patch ⇒ No
State ⇒ Unconfirmed
Milestone ⇒
Queue ⇒ Synchronization
Summary ⇒ ActiveSync SQL error
Type ⇒ Bug
Priority ⇒ 2. Medium
Reply to this comment
currently our logs are filled with those (postgres) SQL errors:

2015-12-03T08:33:33+00:00 ERR: HORDE Returning HTTP 500 while handling 
Sync command. Error is: Protocol error [pid 20755 on line 160 of 
"www/rpc.php"]
2015-12-03T08:33:33+00:00 ERR: HORDE Error in communicating with 
ActiveSync server: Protocol error [pid 20755 on line 165 of 
"pear/php/Horde/Rpc/ActiveSync.php"]
2015-12-03T08:33:33+00:00 ERR: HORDE #0 
pear/php/Horde/ActiveSync/Request/Sync.php(201): 
Horde_ActiveSync_Request_Sync->_parseSyncFolders()
#1 pear/php/Horde/ActiveSync/Request/Base.php(253): 
Horde_ActiveSync_Request_Sync->_handle()
#2 pear/php/Horde/ActiveSync.php(803): Horde_ActiveSync_Request_Base->handle()
#3 pear/php/Horde/Rpc/ActiveSync.php(143): 
Horde_ActiveSync->handleRequest('Sync', 'SEC17314EC9E896...')
#4 www/rpc.php(160): Horde_Rpc_ActiveSync->getResponse(NULL)
#5 {main} [pid 20755 on line 165 of "pear/php/Horde/Rpc/ActiveSync.php"]
2015-12-03T08:33:33+00:00 ERR: HORDE Buffer contents:  [pid 20755 on 
line 165 of "pear/php/Horde/Rpc/ActiveSync.php"]
2015-12-03T09:35:15+01:00 ERR: HORDE [kronolith] SQL QUERY FAILED: 
SQLSTATE[42883]: Undefined function: 7 ERROR:  operator does not 
exist: character varying = integer
LINE 1: ...ginaldate FROM kronolith_events WHERE calendar_id = 0 AND ev...
                                                              ^
HINT:  No operator matches the given name and argument type(s). You 
might need to add explicit type casts.
         SELECT event_id, event_uid, event_description, event_location,
           event_private, event_status, event_attendees, event_title,
           event_recurcount, event_url, event_timezone, event_recurtype,
           event_recurenddate, event_recurinterval, event_recurdays, 
event_start,
           event_end, event_allday, event_alarm, event_alarm_methods,
           event_modified, event_exceptions, event_creator_id, event_resources,
           event_baseid, event_exceptionoriginaldate FROM 
kronolith_events WHERE
           calendar_id = 0 AND event_alarm > 0 AND ((event_end >= '2015-12-02
           23:00:00') OR (event_recurenddate >= '2015-12-02 23:00:00' AND
           event_recurtype <> 0)) [pid 24338 on line 234 of 
"pear/php/Horde/Db/Adapter/Pdo/Base.php"]

Not exactly sure how the problem presents to users. The affected 
clients seem to cause quite more sync traffic though.

Saved Queries