[horde] Debugging ActiveSync GAL search

lst_hoe02 at kwsoft.de lst_hoe02 at kwsoft.de
Wed Aug 27 16:28:22 UTC 2014 

Hello,

we noticed today that our GAL search does not work anymore, atleast  
with some devices. With a Samsung S4 we got the following in the debug  
log:

2014-08-27T18:03:41+02:00 INFO: [12494]  
Horde_Core_ActiveSync_Driver::authenticate() attempt for xxxx
2014-08-27T18:03:41+02:00 INFO: [12494] SEARCH request received for user xxxx
2014-08-27T18:03:41+02:00 INFO: [12494] Device entry exists for  
SEC19F752A0EF5AD, updating userAgent and version.
2014-08-27T18:03:41+02:00 INFO: [12494] Request being handled for  
device: SEC19F752A0EF5AD, Supporting protocol version: 14.1, Using  
Horde_ActiveSync v2.18.0
2014-08-27T18:03:41+02:00 INFO: [12494] GET VARIABLES: Array
(
     [Cmd] => Search
     [User] => xxxx
     [DeviceId] => SEC19F752A0EF5AD
     [DeviceType] => SAMSUNGGTI9295
)

2014-08-27T18:03:41+02:00 INFO: [SEC19F752A0EF5AD] Handling SEARCH command.
2014-08-27T18:03:41+02:00 DEBUG: [12494] I  <Search:Search>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I   <Search:Store>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I    <Search:Name>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I      GAL
2014-08-27T18:03:41+02:00 DEBUG: [12494] I    </Search:Name>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I    <Search:Query>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I      huer
2014-08-27T18:03:41+02:00 DEBUG: [12494] I    </Search:Query>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I    <Search:Options>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I     <Search:Range>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I       0-19
2014-08-27T18:03:41+02:00 DEBUG: [12494] I     </Search:Range>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I     <Search:Picture>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I      <Search:MaxSize>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I        102400
2014-08-27T18:03:41+02:00 DEBUG: [12494] I      </Search:MaxSize>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I      <Search:MaxPictures>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I        20
2014-08-27T18:03:41+02:00 DEBUG: [12494] I      </Search:MaxPictures>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I     </Search:Picture>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I    </Search:Options>
2014-08-27T18:03:41+02:00 DEBUG: [12494] I   </Search:Store>
2014-08-27T18:03:41+02:00 DEBUG: [12494] O  <Search:Search>
2014-08-27T18:03:41+02:00 DEBUG: [12494] O   <Search:Status>
2014-08-27T18:03:41+02:00 DEBUG: [12494] O    1
2014-08-27T18:03:41+02:00 DEBUG: [12494] O   </Search:Status>
2014-08-27T18:03:41+02:00 DEBUG: [12494] O   <Search:Response>
2014-08-27T18:03:41+02:00 DEBUG: [12494] O    <Search:Store>
2014-08-27T18:03:41+02:00 DEBUG: [12494] O     <Search:Status>
2014-08-27T18:03:41+02:00 DEBUG: [12494] O      1
2014-08-27T18:03:41+02:00 DEBUG: [12494] O     </Search:Status>
2014-08-27T18:03:41+02:00 DEBUG: [12494] O    </Search:Store>
2014-08-27T18:03:41+02:00 DEBUG: [12494] O   </Search:Response>
2014-08-27T18:03:41+02:00 DEBUG: [12494] O  </Search:Search>
2014-08-27T18:03:41+02:00 INFO: [12494] Maximum memory usage for  
ActiveSync request: 5647916 bytes.


The GAL is set to a central LDAP directory and the direct query does  
return a lot of entries. Tested against an other Testystem the GAL  
always returns all entries like this:


2014-08-27T18:14:25+02:00 INFO: [21855]  
Horde_Core_ActiveSync_Driver::authenticate() attempt for xxxxx
2014-08-27T18:14:25+02:00 INFO: [21855] SEARCH request received for user xxxxx
2014-08-27T18:14:25+02:00 INFO: [21855] Device entry exists for  
SEC19F752A0EF5AD, updating userAgent and version.
2014-08-27T18:14:25+02:00 INFO: [21855] Request being handled for  
device: SEC19F752A0EF5AD, Supporting protocol version: 14.1, Using  
Horde_ActiveSync v2.18.0
2014-08-27T18:14:25+02:00 INFO: [21855] GET VARIABLES: Array
(
     [Cmd] => Search
     [User] => xxxxx
     [DeviceId] => SEC19F752A0EF5AD
     [DeviceType] => SAMSUNGGTI9295
)

2014-08-27T18:14:25+02:00 INFO: [SEC19F752A0EF5AD] Handling SEARCH command.
2014-08-27T18:14:25+02:00 DEBUG: [21855] I  <Search:Search>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I   <Search:Store>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I    <Search:Name>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I      GAL
2014-08-27T18:14:25+02:00 DEBUG: [21855] I    </Search:Name>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I    <Search:Query>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I      haider
2014-08-27T18:14:25+02:00 DEBUG: [21855] I    </Search:Query>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I    <Search:Options>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I     <Search:Range>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I       0-19
2014-08-27T18:14:25+02:00 DEBUG: [21855] I     </Search:Range>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I     <Search:Picture>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I      <Search:MaxSize>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I        102400
2014-08-27T18:14:25+02:00 DEBUG: [21855] I      </Search:MaxSize>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I      <Search:MaxPictures>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I        20
2014-08-27T18:14:25+02:00 DEBUG: [21855] I      </Search:MaxPictures>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I     </Search:Picture>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I    </Search:Options>
2014-08-27T18:14:25+02:00 DEBUG: [21855] I   </Search:Store>
2014-08-27T18:14:26+02:00 INFO: [21855]  
Horde_Core_ActiveSync_Driver::_searchGal() found 49 matches.
2014-08-27T18:14:26+02:00 DEBUG: [21855] O  <Search:Search>
2014-08-27T18:14:26+02:00 DEBUG: [21855] O   <Search:Status>
2014-08-27T18:14:26+02:00 DEBUG: [21855] O    1
2014-08-27T18:14:26+02:00 DEBUG: [21855] O   </Search:Status>
2014-08-27T18:14:26+02:00 DEBUG: [21855] O   <Search:Response>
2014-08-27T18:14:26+02:00 DEBUG: [21855] O    <Search:Store>
2014-08-27T18:14:26+02:00 DEBUG: [21855] O     <Search:Status>
2014-08-27T18:14:26+02:00 DEBUG: [21855] O      1
2014-08-27T18:14:26+02:00 DEBUG: [21855] O     </Search:Status>
2014-08-27T18:14:26+02:00 DEBUG: [21855] O     <Search:Result>

--cut--

2014-08-27T18:14:26+02:00 DEBUG: [21855] O     </Search:Result>
2014-08-27T18:14:26+02:00 DEBUG: [21855] O     <Search:Range>
2014-08-27T18:14:26+02:00 DEBUG: [21855] O      0-19
2014-08-27T18:14:26+02:00 DEBUG: [21855] O     </Search:Range>
2014-08-27T18:14:26+02:00 DEBUG: [21855] O     <Search:Total>
2014-08-27T18:14:26+02:00 DEBUG: [21855] O      49
2014-08-27T18:14:26+02:00 DEBUG: [21855] O     </Search:Total>
2014-08-27T18:14:26+02:00 DEBUG: [21855] O    </Search:Store>
2014-08-27T18:14:26+02:00 DEBUG: [21855] O   </Search:Response>
2014-08-27T18:14:26+02:00 DEBUG: [21855] O  </Search:Search>
2014-08-27T18:14:26+02:00 INFO: [21855] Maximum memory usage for  
ActiveSync request: 5788476 bytes.

Any chance that GAL always returns alle entries and in the first case  
the answer is dropped because it is to much data??

Any idea how to debug further?

Regards

Andreas

More information about the horde mailing list