[horde] Bad log level META

Mon Feb 20 11:54:54 UTC 2017

Hi

Since updating via git yesterday AM, ActiveSync has stopped working
(i.e. IMP is working fine).

Attempting to to go to .../admin/activesync.php in the browser (to
clear the devices as my first troubleshooting step), give this error:

A fatal error has occurred

Bad log level META

in /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync/Log/Logger/Deprecated.php:52

1. Horde_ActiveSync_SyncCache->__construct()
/usr/share/git-horde5/horde/admin/activesync.php:99
2. Horde_ActiveSync_Log_Logger_Deprecated->meta()
/usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync/SyncCache.php:127
3. Horde_ActiveSync_Log_Logger_Deprecated->__call()
/usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync/SyncCache.php:127

Details

The full error message is logged in Horde's log file, and is shown
below only to administrators. Non-administrative users will not see
error details.

Horde_Log_Exception Object
(
    [details] =>
    [logged] => 1
    [_logLevel:protected] => 0
    [message:protected] => Bad log level META
    [string:Exception:private] =>
    [code:protected] => 0
    [file:protected] =>
/usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync/Log/Logger/Deprecated.php
    [line:protected] => 52
    [trace:Exception:private] => Array

Checking Horde's log file I find..

2017-02-20T11:09:49+00:00 ERR: HORDE-BETA Buffer contents:  [pid 16901
on line 165 of "/usr/share/php/Horde/Rpc/ActiveSync.php"]
2017-02-20T11:09:50+00:00 ERR: HORDE-BETA Returning HTTP 500 while
handling Ping command. Error is: Bad log level INFO [pid 16886 on line
163 of "/usr/share/git-horde5/horde/rpc.php"]
2017-02-20T11:09:50+00:00 ERR: HORDE-BETA Error in communicating with
ActiveSync server: Bad log level INFO [pid 16886 on line 165 of
"/usr/share/php/Horde/Rpc/ActiveSync.php"]
2017-02-20T11:09:50+00:00 ERR: HORDE-BETA #0
/usr/share/git-horde5/framework/Core/lib/Horde/Core/ActiveSync/Driver.php(201):
Horde_ActiveSync_Log_Logger->__call('info', Array)
#1 /usr/share/git-horde5/framework/Core/lib/Horde/Core/ActiveSync/Driver.php(201):
Horde_ActiveSync_Log_Logger->info('----------Horde...')
#2 /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php(578):
Horde_Core_ActiveSync_Driver->authenticate('username at server.n...',
'MungedPassw...', NULL)
#3 /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php(753):
Horde_ActiveSync->authenticate(Object(Horde_ActiveSync_Credentials))
#4 /usr/share/php/Horde/Rpc/ActiveSync.php(143):
Horde_ActiveSync->handleRequest('Ping', 'ADUMD67L3135B8D...')
#5 /usr/share/git-horde5/horde/rpc.php(163):
Horde_Rpc_ActiveSync->getResponse(NULL)
#6 {main} [pid 16886 on line 165 of "/usr/share/php/Horde/Rpc/ActiveSync.php"]
2017-02-20T11:09:50+00:00 ERR: HORDE-BETA Buffer contents:  [pid 16886
on line 165 of "/usr/share/php/Horde/Rpc/ActiveSync.php"]
2017-02-20T11:10:46+00:00 ERR: HORDE-BETA Returning HTTP 500 while
handling Ping command. Error is: Bad log level INFO [pid 16806 on line
163 of "/usr/share/git-horde5/horde/rpc.php"]
2017-02-20T11:10:46+00:00 ERR: HORDE-BETA Error in communicating with
ActiveSync server: Bad log level INFO [pid 16806 on line 165 of
"/usr/share/php/Horde/Rpc/ActiveSync.php"]
2017-02-20T11:10:46+00:00 ERR: HORDE-BETA #0
/usr/share/git-horde5/framework/Core/lib/Horde/Core/ActiveSync/Driver.php(201):
Horde_ActiveSync_Log_Logger->__call('info', Array)
#1 /usr/share/git-horde5/framework/Core/lib/Horde/Core/ActiveSync/Driver.php(201):
Horde_ActiveSync_Log_Logger->info('----------Horde...')
#2 /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php(578):
Horde_Core_ActiveSync_Driver->authenticate('username at server.n...',
'MungedPassw...', NULL)
#3 /usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync.php(753):
Horde_ActiveSync->authenticate(Object(Horde_ActiveSync_Credentials))
#4 /usr/share/php/Horde/Rpc/ActiveSync.php(143):
Horde_ActiveSync->handleRequest('Ping', '4e696e654339383...')
#5 /usr/share/git-horde5/horde/rpc.php(163):
Horde_Rpc_ActiveSync->getResponse(NULL)
#6 {main} [pid 16806 on line 165 of "/usr/share/php/Horde/Rpc/ActiveSync.php"]
2017-02-20T11:10:46+00:00 ERR: HORDE-BETA Buffer contents:  [pid 16806
on line 165 of "/usr/share/php/Horde/Rpc/ActiveSync.php"]
2017-02-20T11:11:40+00:00 EMERG: HORDE-BETA [horde] Bad log level META
[pid 16886 on line 52 of
"/usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync/Log/Logger/Deprecated.php"]
2017-02-20T11:12:39+00:00 EMERG: HORDE-BETA [horde] Bad log level META
[pid 27612 on line 52 of
"/usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync/Log/Logger/Deprecated.php"]
2017-02-20T11:18:28+00:00 EMERG: HORDE-BETA [horde] Bad log level META
[pid 16880 on line 52 of
"/usr/share/git-horde5/framework/ActiveSync/lib/Horde/ActiveSync/Log/Logger/Deprecated.php"]

I reran the git update commands:
cd /usr/share/git-horde5
# update the channel
pear channel-update pear.horde.org
# do the pull
git pull  1>&2 >> git.pull.log
php ./framework/bin/install_dev

But the problem persists..

The log file directory is 660 for www-data, so that shouldn't be an issue.

The conf.php active sync entries are:

$conf['activesync']['params']['driverconfig'] = 'horde';
$conf['activesync']['storage'] = 'Sql';
$conf['activesync']['no_maillogsync'] = false;
$conf['activesync']['emailsync'] = true;
$conf['activesync']['version'] = '16.0';
$conf['activesync']['auth']['type'] = 'basic';
$conf['activesync']['autodiscovery'] = 'full';
$conf['activesync']['hosts']['imap']['host'] = 'mail.server.net';
$conf['activesync']['hosts']['imap']['port'] = 143;
$conf['activesync']['hosts']['imap']['encryption'] = 'TLS';
$conf['activesync']['hosts']['pop']['encryption'] = 'TLS';
$conf['activesync']['hosts']['smtp']['host'] = 'mail.server.net';
$conf['activesync']['hosts']['smtp']['port'] = 587;
$conf['activesync']['hosts']['smtp']['popauth'] = false;
$conf['activesync']['hosts']['smtp']['encryption'] = 'TLS';
$conf['activesync']['outlookdiscovery'] = true;
$conf['activesync']['logging']['path'] = '/var/log/horde/sync/beta/';
$conf['activesync']['logging']['level'] = '2';
$conf['activesync']['logging']['type'] = 'perdevice';
$conf['activesync']['ping']['heartbeatmin'] = 60;
$conf['activesync']['ping']['heartbeatmax'] = 2700;
$conf['activesync']['ping']['heartbeatdefault'] = 480;
$conf['activesync']['ping']['deviceping'] = true;
$conf['activesync']['ping']['waitinterval'] = 5;
$conf['activesync']['ping']['maximumwindowsize'] = 0;
$conf['activesync']['ping']['maximumrequestwindowsize'] = 0;
$conf['activesync']['enabled'] = true;

I tried to disable the logging but that doesn't change anything either..

Any ideas?

Thanks.

Simon