z-push2 does not retrieve emails (log)

[rufi]

Hi,

I'm trying to make z-push function with fast-cgi. Before switching to fast-cgi, everything worked OK using mod_php. However, I have to run apache in worker mode.

I've followed the related topic Working Solution for Z-Push and PHP in (Fast)CGI Mode (viewtopic.php?f=4&t=1245&p=5121&hilit=fast+cgi#p4762), and although it did solved in part a problem, I have another major issue, maybe similar to other topics ("Z-Push 2.0 alpha2 released"), but unresolved.

I am syncing the emails using an iphone and I can authenticate successfully. On the iphone, it seems to fully connect to the server and does not report any error. However, about 2 minutes later, the iphone displays [unable to read mail. Server error, contact the administrator].

I tried all versions of z-push and none work, but I am using z-push 2.0 alpha 2 right now.

Any idea on how to make z-push2 work with fast-cgi and/or how to resolve this problem (which render z-push unusable) ?


The error log file is empty.
The other log file contains:

09/10/2011 02:15:49 [ 2221] [DEBUG] -------- Start
09/10/2011 02:15:49 [ 2221] [ INFO] Version='z-push-2.0alpha2-777' method='OPTIONS' from='FROMIP' cmd='' getUser='' devId='' devType=''
09/10/2011 02:15:49 [ 2221] [DEBUG] NoPostRequestException: Options request - code: 1
09/10/2011 02:15:49 [ 2221] [ INFO] Options request
09/10/2011 02:15:49 [ 2221] [DEBUG] -------- End
...
09/10/2011 02:15:51 [ 2234] [USER] [ INFO] BackendIMAP->Logon(): User 'USER' is authenticated on IMAP
09/10/2011 02:15:51 [ 2234] [USER] [DEBUG] ZPush::CommandNeedsPlainInput('FolderSync'): false
09/10/2011 02:15:51 [ 2234] [USER] [ WARN] The HierarchyCache should have been initialized by now. Getting empty cache
09/10/2011 02:15:51 [ 2234] [USER] [DEBUG] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 0
09/10/2011 02:15:51 [ 2234] [USER] [DEBUG] Initializing folder diff engine
09/10/2011 02:15:51 [ 2234] [USER] [DEBUG] ImportChangesDiff->InitializeExporter(): Initializing folder diff engine
09/10/2011 02:15:51 [ 2234] [USER] [ WARN] ...z-push-2.0a2/backend/imap.php:619 Undefined property: BackendIMAP::$_server (8)
09/10/2011 02:15:51 [ 2234] [USER] [ WARN] ...z-push-2.0a2/backend/imap.php:619 Undefined property: BackendIMAP::$_server (8)
09/10/2011 02:15:51 [ 2234] [USER] [ WARN] ...z-push-2.0a2/backend/imap.php:619 Undefined property: BackendIMAP::$_server (8)
09/10/2011 02:15:51 [ 2234] [USER] [ WARN] ...z-push-2.0a2/backend/imap.php:619 Undefined property: BackendIMAP::$_server (8)
...
09/10/2011 02:15:52 [ 2234] [USER] [DEBUG] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 25
09/10/2011 02:15:52 [ 2234] [USER] [DEBUG] FileStateMachine->SetState() written 18196 bytes on file: '/var/lib/z-push/t/4/ApplXXXXXX$
09/10/2011 02:15:52 [ 2234] [USER] [DEBUG] FileStateMachine->SetState() written 4971 bytes on file: '/var/lib/z-push/t/4/ApplXXXXXX-$
09/10/2011 02:15:52 [ 2234] [USER] [DEBUG] BackendIMAP->Logoff(): IMAP connection closed
09/10/2011 02:15:52 [ 2234] [USER] [DEBUG] DeviceManager->Save(): Device data changed
09/10/2011 02:15:52 [ 2234] [USER] [DEBUG] FileStateMachine->SetState() written 2493 bytes on file: '/var/lib/z-push/t/4/ApplXXXXXXXXX-devicedata'
09/10/2011 02:15:52 [ 2234] [USER] [DEBUG] DeviceManager->Save(): Device data saved
09/10/2011 02:15:52 [ 2234] [USER] [DEBUG] -------- End
...
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] -------- Start
09/10/2011 02:17:03 [ 2396] [USER] [ INFO] Version='z-push-2.0alpha2-777' method='POST' from='FROMIP' cmd='Sync' getUser='USER' devId='ApplXXXXXXXXXXXX$
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] Used timezone 'America/Montreal'
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] Including backend file: '...z-push2/backend/imap.php'
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] Incoming PolicyKey: 2518006593
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] Client supports version: 2.5
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] ZPush::CommandNeedsProvisioning('Sync'): true
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] ASDevice initialized for DeviceID 'ApplXXXXXXXXXX'
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] FileStateMachine->GetState() on file: '/var/lib/z-push/t/4/ApplXXXXXXXXXX-devicedata'
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] ASDevice data loaded for user: 'USER'
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] ZPush::HierarchyCommand('Sync'): false
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] DeviceManager->ProvisioningRequired('2518006593') saved device key '2518006593': false
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] ZPush::CommandNeedsAuthentication('Sync'): true
09/10/2011 02:17:03 [ 2396] [USER] [ INFO] BackendIMAP->Logon(): User 'USER' is authenticated on IMAP
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] ZPush::CommandNeedsPlainInput('Sync'): false
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] Sync folder: 'Email'
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] ZPush::GetAdditionalSyncFolderStore('INBOX'): 'false'
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] ImportChangesDiff->InitializeExporter(): Initializing message diff engine. '0' messages in state
09/10/2011 02:17:03 [ 2396] [USER] [DEBUG] BackendIMAP->GetMessageList('INBOX','1315462623')
09/10/2011 02:17:06 [ 2396] [USER] [DEBUG] Received date is false. Message might be broken.
09/10/2011 02:17:06 [ 2396] [USER] [ INFO] ImportChangesDiff->InitializeExporter(): Found '50' changes
09/10/2011 02:17:06 [ 2396] [USER] [ WARN] StatusException: DiffState->GetState(): Error, state not available - code: 12
09/10/2011 02:17:06 [ 2396] [USER] [ INFO] User-agent: 'Apple-iPhone3C1/810.2'
09/10/2011 02:17:06 [ 2396] [USER] [DEBUG] ZPush::PrintZPushLegal()


About the getState error:

09/10/2011 02:43:06 [ 1942] [USER] [ERROR] Exception: DiffState->GetState(): Error, state not available

Trace:
Array
(
[0] => Array
(
[file] => .../z-push-2.0a2/lib/requestprocessor.php
[line] => 1062
[function] => GetState
[class] => DiffState
[type] => ->
[args] => Array
(
)

)

[1] => Array
(
[file] => .../z-push-2.0a2/lib/requestprocessor.php
[line] => 124
[function] => HandleSync
[class] => RequestProcessor
[type] => ::
[args] => Array
(
)

)

[2] => Array
(
[file] => ...html/z-push-2.0a2/index.php
[line] => 128
[function] => HandleRequest
[class] => RequestProcessor
[type] => ::
[args] => Array
(
)

)

)


09/10/2011 02:17:06 [ 2396] [USER] [DEBUG] -------- End

[rufi]

Hi,

I debugged the code further and made a small change.
"z-push-2.0a2/backend/imap.php:619 Undefined property: BackendIMAP::$_server (8)"
There is a typo in the code, so I simply changed _server to server.

"StatusException: DiffState->GetState(): Error, state not available - code: 12"
in lib/requestprocessor.php : 1062...
I moved the last condition in front of the others:

Code: Select all

   // if a new request without state information (hierarchy) save an empty state
                        if ($collection["synckey"] == "0")
                            $state = "";
                        else if (isset($exporter) && $exporter)
                            $state = $exporter->GetState();
...


I can confirm (just tested it) that this resolves my problem and I can now retrieve the emails correctly.

However, I still have one warning in the log files that I did not fix - but it seems relatively minor - hopefully the devs can fix it:
[ WARN] /z-push-2.0a2/backend/imap.php:936 array_push() expects parameter 1 to be array, null given (2)

[mku]

Hi rufi,

Z-Push 2 is not a stable version yet, so it might contain some bugs or not work as expected. We will look at this.

Thank you for testing and please let us know if you find any issues.

Greets, Manfred

[rufi]

Hi mku,

I'm happy to test it out. It seems that z-push2 include several fixes and improvements based on my previous experience with z-push+iphone setup.

Please note that the changes I reported are still there on the trunk so you might want to fix it eventually. I simply added "$output->attachments = array();" in front of "array_push($output->attachments, $attachment);" to prevent the warning above in my version.

Unfortunately, even with all these small changes, it no longer works. It worked before (using iphone 4 IOS 4.3.3 and today, using IOS 5 it seems to have broken z-push - not sure why). I am trying all versions of z-push to no avail. Using the latest stable one 1.5.5 I get "cannot connect to server error" and debug.txt contains no useful informations. Using 1.4.2. I get a little more infos:

10/12/11 01:13:33 [28725] Start
10/12/11 01:13:33 [28725] Z-Push version: 1.4.2 473
10/12/11 01:13:33 [28725] Client IP: xxxxxxx
10/12/11 01:13:33 [28725] Client supports version 2.5
10/12/11 01:13:33 [28725] IMAP connection opened sucessfully
10/12/11 01:13:33 [28725] POST cmd: Provision
10/12/11 01:13:33 [28725] IMAP connection closed
10/12/11 01:13:33 [28725] end
10/12/11 01:13:33 [28725] --------
10/12/11 01:13:34 [28730] Start
10/12/11 01:13:34 [28730] Z-Push version: 1.4.2 473
10/12/11 01:13:34 [28730] Client IP: xxxx
10/12/11 01:13:34 [28730] Client supports version 2.5
10/12/11 01:13:34 [28730] IMAP connection opened sucessfully
10/12/11 01:13:34 [28730] POST cmd Sync denied: Retry after sending a PROVISION command
10/12/11 01:13:34 [28730] end
10/12/11 01:13:34 [28730] --------


Then it seems to loop forever until I kill it.

EDIT:Finally, using 1.5.5, all folders (even large ones) seem to sync well... however, the "INBOX" folder reports the [cannot connect to server error]. In addition, I can make it work if I set up my iphone to only get the last 7 days of email (instead of 1 month long). In the log I have "Change for folder 'Inbox' will not be sent as modification is not relevant" even though it failed last time and is empty. When it does fail (e.g. for the INBOX folder and for 1 month log time period, the iphone progress bar shows "downloading..." several times in a row then it shows the cannot connect error message. In the log I get...

10/12/11 08:20:58 [2761] [USER] IMAP-StatMessage: (fid: 'INBOX' id: '5183' )
10/12/11 08:20:58 [2761] [USER] IMAP-GetMessage: (fid: 'INBOX' id: '5183' truncsize: 512)
10/12/11 08:20:58 [2761] [USER] IMAP-StatMessage: (fid: 'INBOX' id: '5183' )
10/12/11 08:20:58 [2761] [USER] IMAP-StatMessage: (fid: 'INBOX' id: '5182' )
10/12/11 08:20:58 [2761] [USER] IMAP-GetMessage: (fid: 'INBOX' id: '5182' truncsize: 512)
10/12/11 08:20:58 [2761] [USER] IMAP-StatMessage: (fid: 'INBOX' id: '5182' )
...
10/12/11 08:20:58 [2761] [USER] IMAP-GetMessage: (fid: 'INBOX' id: '5179' truncsize: 512)
10/12/11 08:20:58 [2761] [USER] IMAP-StatMessage: (fid: 'INBOX' id: '5179' )
10/12/11 08:20:58 [2761] [USER] IMAP-StatMessage: (fid: 'INBOX' id: '5178' )
10/12/11 08:20:58 [2761] [USER] IMAP-GetMessage: (fid: 'INBOX' id: '5178' truncsize: 512)
10/12/11 08:20:58 [2761] [USER] IMAP-StatMessage: (fid: 'INBOX' id: '5178' )
10/12/11 08:20:58 [2761] [USER] IMAP connection closed
10/12/11 08:20:58 [2761] [USER] end

The log if INBOX but for less than a month duration:

10/12/11 08:22:10 [2871] [USER] IMAP connection opened sucessfully
10/12/11 08:22:10 [2871] [USER] POST cmd: FolderSync
10/12/11 08:22:10 [2871] [USER] Initializing folder diff engine
10/12/11 08:22:10 [2871] [USER] Found 4 folder changes
10/12/11 08:22:10 [2871] [USER] Change for folder 'Inbox' will not be sent as modification is not relevant
...
10/12/11 08:22:10 [2871] [USER] IMAP connection closed
10/12/11 08:22:10 [2871] [USER] end
10/12/11 08:22:10 [2871] [USER] --------
10/12/11 08:22:10 [2876] [USER] Start
10/12/11 08:22:10 [2876] [USER] Z-Push version: 1.5.5-790
10/12/11 08:22:10 [2876] [USER] Client IP: XXXXX
10/12/11 08:22:10 [2876] [USER] Client supports version 2.5
10/12/11 08:22:10 [2876] [USER] IMAP connection opened sucessfully
10/12/11 08:22:10 [2876] [USER] POST cmd: Sync
10/12/11 08:22:10 [2876] [USER] Sync folder:Email
10/12/11 08:22:10 [2876] [USER] Initializing message diff engine
10/12/11 08:22:10 [2876] [USER] 9 messages in state
10/12/11 08:22:10 [2876] [USER] IMAP-GetMessageList: (fid: 'INBOX' cutdate: '1317795730' )
10/12/11 08:22:11 [2876] [USER] Found 0 message changes
10/12/11 08:22:11 [2876] [USER] IMAP connection closed
10/12/11 08:22:11 [2876] [USER] end
10/12/11 08:22:11 [2876] [USER] --------


Thanks for any insight

[skummer]

Hi,

well, these are several things.

About the issue with the initial sync, please see: viewtopic.php?f=2&t=1658&p=6143#p6143

About the large folders: How long does it take for the process to complete? It could just be that the phone times out e.g. after 10 seconds. This would explain why 7 days work while 1 month not. Perhaps it just takes "too long".

About the "modification is not relevant": this happens only during the foldersync and is something normal in certain moments. For ActiveSync only the name, the type, the ID and the parentID of a folder are interesting. All other changes are ignored. This message appears if a folder was "marked as changed" but no actual data change could be detected.
Could you check what exactly triggered the changed for this folder?

Thx for testing!

Cheers,
Sebastian