1 Topic by nowhere99 (edited by nowhere99 2020-04-22 05:25:59)

  • nowhere99
  • Member
  • Offline
  • Registered: 2017-11-10
  • Posts: 26

Topic: Trouble connecting to EAS

==== REQUIRED BASIC INFO OF YOUR IREDMAIL SERVER ====
- iRedMail version (check /etc/iredmail-release): 0.9.9 MYSQL edition.
- Deployed with iRedMail Easy or the downloadable installer? downloadable
- Linux/BSD distribution name and version: Ubuntu 18.04.4
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MySQL
- Web server (Apache or Nginx): Nginx
- Manage mail accounts with iRedAdmin-Pro? No
- [IMPORTANT] Related original log or error message is required if you're experiencing an issue.
====
I am having trouble connecting clients to the Exchange ActiveSync. Here are the symptoms
1. IMAP works on phone (i.e. I know the correct username and password). I need ActiveSync for calendar and contacts on phone
2. The rest of family was already having this problem having set up mail much more recently on their devices
3. It was working on my Android 9 phone using Vmare Boxer for >1 year
4. I had to do a factory reset on the phone, reinstall and now Boxer and Bluemail apps both complain with various responses.
        Add Account -> Exchange, has fields for
            email addy (I add full email)
            DOMAIN\Username (I add full email)
            Password
            Checkbox for Automatic (I uncheck)
            Checkbox for Prefer ActiveSync (I check)
        This Opens manual entry screen, with added fields:
            Exchange server (set to FQDN of my server)
            Security (set to SSL/TLS)
            Client Certificate: None
            Port: 443
        Error: "You typed an incorrect server address or the server requires a protocol version that Email doesn't support(0)"
        If I change the Domain\Username to my domain only, Error changes to "Username or password incorrect(1)"
        I've tried:
            domain.net -> bad username password
            user@domain.net -> incorrect server address
            domain.net\user -> bad username password
            domain.net\user@domain.net -> incorrect server address
            \user@domain.net -> incorrect server address
5. I have the same problems configuring Outlook 2016 in Windows 10
6. IMAP works with Thunderbird in Windows and Linux

So I'm pretty sure it's a EAS problem or problem configuring the connect to EAS.

Messages in sogo.log (with SOGoEASDebugEnabled = YES)

whenever I try to do the connect when it produces the incorrect server address error

Apr 21 14:25:48 sogod [1358]: mx.domain.net "OPTIONS /SOGo/Microsoft-Server-ActiveSync HTTP/1.0" 200 0/0 0.002 - - 0

and I get this message when wrong username/password

Apr 21 14:29:17 sogod [1358]: <0x0x561b5b314380[SOGoDAVAuthenticator]> tried wrong password for user 'domain.net'!
Apr 21 14:29:17 sogod [1358]: mx.domain.net "OPTIONS /SOGo/Microsoft-Server-ActiveSync HTTP/1.0" 401 12/0 0.002 - - 0

Any help?

Thanks!

----

Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.

2 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,088

Re: Trouble connecting to EAS

the URL /SOGo/Microsoft-Server-ActiveSync is internal URL used by SOGo, which was redirected by Nginx from /Microsoft-Server-ActiveSync. it's correct.

We need more debug log from sogo log file for troubleshooting.

3 Reply by nowhere99

  • nowhere99
  • Member
  • Offline
  • Registered: 2017-11-10
  • Posts: 26

Re: Trouble connecting to EAS

ZhangHuangbin wrote:

We need more debug log from sogo log file for troubleshooting.

Thanks Zhang, I restarted the server for a full startup log. Here's the full log. user1 is the user I'm trying to add an Exchange client for. 

Apr 22 10:34:33 sogod [17227]: <0x0x5652e1fa0ba0[WOWatchDog]> all children exited. We now terminate.
Apr 22 10:34:33 sogod [10669]: version 4.3.0 (build @shiva2.inverse 202004220243) -- starting
Apr 22 10:34:33 sogod [10669]: vmem size check enabled: shutting down app when vmem > 500 MB. Currently at 232 MB
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dbecd50[SOGoProductLoader]> SOGo products loaded from '/usr/lib/GNUstep/SOGo':
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dbecd50[SOGoProductLoader]>   Mailer.SOGo, Contacts.SOGo, MainUI.SOGo, MailerUI.SOGo, AdministrationUI.SOGo, MailPartViewers.SOGo, PreferencesUI.SOGo, Appointments.SOGo, ContactsUI.SOGo, SchedulerUI.SOGo, CommonUI.SOGo
Apr 22 10:34:33 sogod [10669]: All products loaded - current memory usage at 284 MB
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> listening on 127.0.0.1:20000
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> watchdog process pid: 10669
Apr 22 10:34:33 sogod [10669]: <0x0x7fe3b3dcb240[WOWatchDogChild]> watchdog request timeout set to 61 minutes
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> preparing 10 children
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> child spawned with pid 10672
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> child spawned with pid 10673
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> child spawned with pid 10674
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> child spawned with pid 10675
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> child spawned with pid 10676
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> child spawned with pid 10677
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> child spawned with pid 10678
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> child spawned with pid 10679
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> child spawned with pid 10680
Apr 22 10:34:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> child spawned with pid 10681
Apr 22 10:34:53 sogod [10679]: <0x0x562b2dc54930[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:34:53 sogod [10672]: <0x0x562b2dbf9d80[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:34:53 sogod [10680]: <0x0x562b2dc133f0[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:34:53 sogod [10681]: <0x0x562b2dc133f0[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:34:53 sogod [10676]: <0x0x562b2dc54930[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:34:53 sogod [10674]: <0x0x562b2dc54b00[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:34:53 sogod [10673]: <0x0x562b2dbfa060[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:34:53 sogod [10677]: <0x0x562b2dd3a440[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:34:53 sogod [10675]: <0x0x562b2dc54b00[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:34:53 sogod [10678]: <0x0x562b2dc54930[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:46:17 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:17 sogod [10669]: <0x0x562b2dd773f0[WOWatchDogChild]> sending terminate signal to pid 10681
Apr 22 10:46:17 sogod [10669]: <0x0x562b2ddb5120[WOWatchDogChild]> sending terminate signal to pid 10680
Apr 22 10:46:17 sogod [10669]: <0x0x562b2dde86b0[WOWatchDogChild]> sending terminate signal to pid 10679
Apr 22 10:46:17 sogod [10669]: <0x0x562b2ddfbc60[WOWatchDogChild]> sending terminate signal to pid 10678
Apr 22 10:46:17 sogod [10669]: <0x0x562b2dcff830[WOWatchDogChild]> sending terminate signal to pid 10677
Apr 22 10:46:17 sogod [10669]: <0x0x562b2dcdf8d0[WOWatchDogChild]> sending terminate signal to pid 10676
Apr 22 10:46:17 sogod [10669]: <0x0x562b2dcdfeb0[WOWatchDogChild]> sending terminate signal to pid 10675
Apr 22 10:46:17 sogod [10669]: <0x0x562b2dd060d0[WOWatchDogChild]> sending terminate signal to pid 10674
Apr 22 10:46:17 sogod [10669]: <0x0x562b2dcfe9c0[WOWatchDogChild]> sending terminate signal to pid 10673
Apr 22 10:46:17 sogod [10669]: <0x0x562b2dcfeef0[WOWatchDogChild]> sending terminate signal to pid 10672
Apr 22 10:46:17 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:18 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:18 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:19 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:19 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:20 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:20 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:21 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:21 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:22 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:22 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:23 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:23 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:24 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:24 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:25 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:25 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:26 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:26 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:27 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:27 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:28 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:28 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:29 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:29 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:30 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:30 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:31 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:31 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:32 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:32 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:33 sogod [10669]: <0x0x562b2dd060d0[WOWatchDogChild]> child 10674 exited
Apr 22 10:46:33 sogod [10669]: <0x0x562b2dcdf8d0[WOWatchDogChild]> child 10676 exited
Apr 22 10:46:33 sogod [10669]: <0x0x562b2ddfbc60[WOWatchDogChild]> child 10678 exited
Apr 22 10:46:33 sogod [10669]: <0x0x562b2dde86b0[WOWatchDogChild]> child 10679 exited
Apr 22 10:46:33 sogod [10669]: <0x0x562b2ddb5120[WOWatchDogChild]> child 10680 exited
Apr 22 10:46:33 sogod [10669]: <0x0x562b2dd773f0[WOWatchDogChild]> child 10681 exited
Apr 22 10:46:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:33 sogod [10669]: <0x0x562b2dcfeef0[WOWatchDogChild]> child 10672 exited
Apr 22 10:46:33 sogod [10669]: <0x0x562b2dcfe9c0[WOWatchDogChild]> child 10673 exited
Apr 22 10:46:33 sogod [10669]: <0x0x562b2dcdfeb0[WOWatchDogChild]> child 10675 exited
Apr 22 10:46:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> Terminating with SIGINT or SIGTERM
Apr 22 10:46:33 sogod [10669]: <0x0x562b2dcff830[WOWatchDogChild]> child 10677 exited
Apr 22 10:46:33 sogod [10669]: <0x0x562b2dc81c50[WOWatchDog]> all children exited. We now terminate.
Apr 22 10:46:53 sogod [1263]: version 4.3.0 (build @shiva2.inverse 202004220243) -- starting
Apr 22 10:46:53 sogod [1263]: vmem size check enabled: shutting down app when vmem > 500 MB. Currently at 232 MB
Apr 22 10:46:54 sogod [1263]: <0x0x5561f4e1ec40[SOGoProductLoader]> SOGo products loaded from '/usr/lib/GNUstep/SOGo':
Apr 22 10:46:54 sogod [1263]: <0x0x5561f4e1ec40[SOGoProductLoader]>   Mailer.SOGo, Contacts.SOGo, MainUI.SOGo, MailerUI.SOGo, AdministrationUI.SOGo, MailPartViewers.SOGo, PreferencesUI.SOGo, Appointments.SOGo, ContactsUI.SOGo, SchedulerUI.SOGo, CommonUI.SOGo
Apr 22 10:46:54 sogod [1263]: All products loaded - current memory usage at 284 MB
Apr 22 10:46:54 sogod [1263]: <0x0x5561f4eb3b40[WOWatchDog]> listening on 127.0.0.1:20000
Apr 22 10:46:54 sogod [1263]: <0x0x5561f4eb3b40[WOWatchDog]> watchdog process pid: 1263
Apr 22 10:46:54 sogod [1263]: <0x0x7fdc0039e240[WOWatchDogChild]> watchdog request timeout set to 61 minutes
Apr 22 10:46:54 sogod [1263]: <0x0x5561f4eb3b40[WOWatchDog]> preparing 10 children
Apr 22 10:46:54 sogod [1263]: <0x0x5561f4eb3b40[WOWatchDog]> child spawned with pid 1547
Apr 22 10:46:54 sogod [1263]: <0x0x5561f4eb3b40[WOWatchDog]> child spawned with pid 1548
Apr 22 10:46:54 sogod [1263]: <0x0x5561f4eb3b40[WOWatchDog]> child spawned with pid 1551
Apr 22 10:46:54 sogod [1263]: <0x0x5561f4eb3b40[WOWatchDog]> child spawned with pid 1552
Apr 22 10:46:54 sogod [1263]: <0x0x5561f4eb3b40[WOWatchDog]> child spawned with pid 1553
Apr 22 10:46:54 sogod [1263]: <0x0x5561f4eb3b40[WOWatchDog]> child spawned with pid 1581
Apr 22 10:46:55 sogod [1263]: <0x0x5561f4eb3b40[WOWatchDog]> child spawned with pid 1583
Apr 22 10:46:55 sogod [1263]: <0x0x5561f4eb3b40[WOWatchDog]> child spawned with pid 1592
Apr 22 10:46:55 sogod [1263]: <0x0x5561f4eb3b40[WOWatchDog]> child spawned with pid 1595
Apr 22 10:46:55 sogod [1263]: <0x0x5561f4eb3b40[WOWatchDog]> child spawned with pid 1596
Apr 22 10:47:25 sogod [1553]: <0x0x5561f4e466f0[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:47:25 sogod [1548]: <0x0x5561f4e865c0[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:47:25 sogod [1596]: <0x0x5561f4e45460[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:47:25 sogod [1583]: <0x0x5561f4e45420[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:47:25 sogod [1552]: <0x0x5561f4e86860[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:47:25 sogod [1595]: <0x0x5561f4e46530[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:47:25 sogod [1547]: <0x0x5561f4e865c0[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:47:25 sogod [1581]: <0x0x5561f4e466f0[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:47:25 sogod [1551]: <0x0x5561f4e46770[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:47:25 sogod [1592]: <0x0x5561f4e466f0[WOHttpAdaptor]> notified the watchdog that we are ready
Apr 22 10:50:08 sogod [1592]: <0x0x5561f4e23710[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
Apr 22 10:50:08 sogod [1592]: <0x0x5561f4e23710[SOGoCache]> Using host(s) '127.0.0.1' as server(s)
Apr 22 10:50:08 sogod [1592]: 192.168.0.2 "PROPFIND /SOGo/dav/user3%40mydomain.net/Calendar/personal/ HTTP/1.0" 401 0/306 0.018 - - 0
Apr 22 10:50:08 sogod [1551]: <0x0x5561f4fc9e60[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
Apr 22 10:50:08 sogod [1551]: <0x0x5561f4fc9e60[SOGoCache]> Using host(s) '127.0.0.1' as server(s)
Apr 22 10:50:08 sogod [1592]: 192.168.0.2 "PROPFIND /SOGo/dav/user5%40mydomain.net/Calendar/personal/ HTTP/1.0" 401 0/306 0.010 - - 1M
Apr 22 10:50:08 sogod [1581]: <0x0x5561f4fb95b0[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
Apr 22 10:50:08 sogod [1581]: <0x0x5561f4fb95b0[SOGoCache]> Using host(s) '127.0.0.1' as server(s)
Apr 22 10:50:08 sogod [1581]: 192.168.0.2 "PROPFIND /SOGo/dav/user1%40mydomain.net/Calendar/personal/ HTTP/1.0" 401 0/306 0.010 - - 1M
Apr 22 10:50:08 sogod [1547]: <0x0x5561f4fb9550[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
Apr 22 10:50:08 sogod [1547]: <0x0x5561f4fb9550[SOGoCache]> Using host(s) '127.0.0.1' as server(s)
Apr 22 10:50:08 sogod [1547]: 192.168.0.2 "PROPFIND /SOGo/dav/user2%40mydomain.net/Calendar/personal/ HTTP/1.0" 401 0/306 0.007 - - 0
Apr 22 10:50:08 sogod [1581]: 192.168.0.2 "PROPFIND /SOGo/dav/user4%40mydomain.net/Calendar/personal/ HTTP/1.0" 401 0/306 0.008 - - 0
Apr 22 10:50:08 sogod [1551]: [WARN] <0x0x5561f4fed0a0[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1551]: [WARN] <0x0x5561f4fed0a0[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1551]: [WARN] <0x0x5561f4fed0a0[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1581]: [WARN] <0x0x5561f4cee4e0[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1581]: [WARN] <0x0x5561f4cee4e0[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1581]: [WARN] <0x0x5561f4cee4e0[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1595]: <0x0x5561f4f5c340[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
Apr 22 10:50:08 sogod [1595]: <0x0x5561f4f5c340[SOGoCache]> Using host(s) '127.0.0.1' as server(s)
Apr 22 10:50:08 sogod [1592]: [WARN] <0x0x5561f4c752d0[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1592]: [WARN] <0x0x5561f4c752d0[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1592]: [WARN] <0x0x5561f4c752d0[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1547]: [WARN] <0x0x5561f4ea6b90[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1547]: [WARN] <0x0x5561f4ea6b90[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1547]: [WARN] <0x0x5561f4ea6b90[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1595]: [WARN] <0x0x5561f4c360f0[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1595]: [WARN] <0x0x5561f4c360f0[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1595]: [WARN] <0x0x5561f4c360f0[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1551]: 192.168.0.2 "PROPFIND /SOGo/dav/user3%40mydomain.net/Calendar/personal/ HTTP/1.0" 207 576/306 0.105 1715 66% 3M
Apr 22 10:50:08 sogod [1581]: 192.168.0.2 "PROPFIND /SOGo/dav/user5%40mydomain.net/Calendar/personal/ HTTP/1.0" 207 576/306 0.076 1715 66% 2M
Apr 22 10:50:08 sogod [1592]: 192.168.0.2 "PROPFIND /SOGo/dav/user2%40mydomain.net/Calendar/personal/ HTTP/1.0" 207 577/306 0.102 1717 66% 4M
Apr 22 10:50:08 sogod [1592]: 192.168.0.2 "OPTIONS /SOGo/dav/user3%40mydomain.net/Calendar/ HTTP/1.0" 401 0/0 0.002 - - 0
Apr 22 10:50:08 sogod [1592]: 192.168.0.2 "OPTIONS /SOGo/dav/user5%40mydomain.net/Calendar/ HTTP/1.0" 401 0/0 0.001 - - 0
Apr 22 10:50:08 sogod [1592]: 192.168.0.2 "OPTIONS /SOGo/dav/user2%40mydomain.net/Calendar/ HTTP/1.0" 401 0/0 0.001 - - 0
Apr 22 10:50:08 sogod [1547]: 192.168.0.2 "PROPFIND /SOGo/dav/user1%40mydomain.net/Calendar/personal/ HTTP/1.0" 207 569/306 0.139 1711 66% 5MApr 22 10:50:08 sogod [1595]: 192.168.0.2 "PROPFIND /SOGo/dav/user4%40mydomain.net/Calendar/personal/ HTTP/1.0" 207 576/306 0.137 1717 66% 3M

Apr 22 10:50:08 sogod [1592]: 192.168.0.2 "OPTIONS /SOGo/dav/user3%40mydomain.net/Calendar/ HTTP/1.0" 200 0/0 0.014 - - 0
Apr 22 10:50:08 sogod [1592]: 192.168.0.2 "OPTIONS /SOGo/dav/user5%40mydomain.net/Calendar/ HTTP/1.0" 200 0/0 0.004 - - 0
Apr 22 10:50:08 sogod [1547]: 192.168.0.2 "OPTIONS /SOGo/dav/user2%40mydomain.net/Calendar/ HTTP/1.0" 200 0/0 0.007 - - 0
Apr 22 10:50:08 sogod [1547]: 192.168.0.2 "OPTIONS /SOGo/dav/user1%40mydomain.net/Calendar/ HTTP/1.0" 401 0/0 0.001 - - 0
Apr 22 10:50:08 sogod [1595]: 192.168.0.2 "PROPFIND /SOGo/dav/user1%40mydomain.net/ HTTP/1.0" 401 0/235 0.003 - - 0Apr 22 10:50:08 sogod [1581]: 192.168.0.2 "PROPFIND /SOGo/dav/user1%40mydomain.net/ HTTP/1.0" 401 0/235 0.004 - - 0

Apr 22 10:50:08 sogod [1581]: 192.168.0.2 "PROPFIND /SOGo/dav/user1%40mydomain.net/ HTTP/1.0" 207 829/235 0.005 - - 0Apr 22 10:50:08 sogod [1595]: 192.168.0.2 "PROPFIND /SOGo/dav/user1%40mydomain.net/ HTTP/1.0" 207 829/235 0.006 - - 0

Apr 22 10:50:08 sogod [1551]: 192.168.0.2 "OPTIONS /SOGo/dav/user1%40mydomain.net/Calendar/ HTTP/1.0" 200 0/0 0.012 - - 0
Apr 22 10:50:08 sogod [1592]: 192.168.0.2 "OPTIONS /SOGo/dav/user4%40mydomain.net/Calendar/ HTTP/1.0" 401 0/0 0.021 - - 0Apr 22 10:50:08 sogod [1547]: 192.168.0.2 "PROPFIND /SOGo/dav/user1%40mydomain.net/ HTTP/1.0" 401 0/235 0.022 - - 0

Apr 22 10:50:08 sogod [1581]: 192.168.0.2 "PROPFIND /SOGo/dav/user1%40mydomain.net/ HTTP/1.0" 207 829/235 0.002 - - 0
Apr 22 10:50:08 sogod [1547]: 192.168.0.2 "PROPFIND /SOGo/dav/user1%40mydomain.net/ HTTP/1.0" 207 829/235 0.017 - - 0
Apr 22 10:50:08 sogod [1581]: 192.168.0.2 "REPORT /SOGo/dav/user3%40mydomain.net/Calendar/personal/ HTTP/1.0" 207 125/188 0.024 - - 0
Apr 22 10:50:08 sogod [1551]: 192.168.0.2 "REPORT /SOGo/dav/user5%40mydomain.net/Calendar/personal/ HTTP/1.0" 207 125/188 0.033 - - 1M
Apr 22 10:50:08 sogod [1552]: <0x0x5561f4f5c450[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
Apr 22 10:50:08 sogod [1552]: <0x0x5561f4f5c450[SOGoCache]> Using host(s) '127.0.0.1' as server(s)
Apr 22 10:50:08 sogod [1592]: 192.168.0.2 "OPTIONS /SOGo/dav/user4%40mydomain.net/Calendar/ HTTP/1.0" 200 0/0 0.038 - - 0Apr 22 10:50:08 sogod [1595]: 192.168.0.2 "REPORT /SOGo/dav/user2%40mydomain.net/Calendar/personal/ HTTP/1.0" 207 125/188 0.054 - - 1M

Apr 22 10:50:08 sogod [1552]: [WARN] <0x0x5561f4c7e4d0[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1552]: [WARN] <0x0x5561f4c7e4d0[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions tableApr 22 10:50:08 sogod [1547]: 192.168.0.2 "REPORT /SOGo/dav/user1%40mydomain.net/Calendar/personal/ HTTP/1.0" 207 125/188 0.028 - - 0

Apr 22 10:50:08 sogod [1552]: [WARN] <0x0x5561f4c7e4d0[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
Apr 22 10:50:08 sogod [1552]: 192.168.0.2 "PROPFIND /SOGo/dav/user1%40mydomain.net/ HTTP/1.0" 207 829/235 0.027 - - 2M
Apr 22 10:50:08 sogod [1552]: 192.168.0.2 "REPORT /SOGo/dav/user4%40mydomain.net/Calendar/personal/ HTTP/1.0" 207 125/188 0.011 - - 992K
Apr 22 10:54:50 sogod [1552]: [WARN] <0x0x7fdc003bfe20[WOxElemBuilder]> could not locate builders: WOxExtElemBuilder,WOxExtElemBuilder
Apr 22 10:54:50 sogod [1552]: 192.168.0.2 "GET /SOGo HTTP/1.0" 302 0/0 0.017 - - 1M
Apr 22 10:54:50 sogod [1552]: 192.168.0.2 "GET /SOGo/ HTTP/1.0" 200 7429/0 0.018 27572 73% 872K
Apr 22 10:54:55 sogod [1552]: SOGoRootPage successful login from '192.168.0.2' for user 'user6@mydomain.net' - expire = -1  grace = -1
Apr 22 10:54:55 sogod [1552]: 192.168.0.2 "POST /SOGo/connect HTTP/1.0" 200 41/80 0.115 - - 0
Apr 22 10:54:56 sogod [1552]: 192.168.0.2 "GET /SOGo/user6%40mydomain.net HTTP/1.0" 302 0/0 0.002 - - 0
Apr 22 10:54:56 sogod [1552]: 192.168.0.2 "GET /SOGo/user6%40mydomain.net/view HTTP/1.0" 302 0/0 0.004 - - 132K
Apr 22 10:54:56 sogod [1552]: 192.168.0.2 "GET /SOGo/so/user6@mydomain.net/Mail HTTP/1.0" 302 0/0 0.002 - - 0
Apr 22 10:54:56 sogod [1552]: 192.168.0.2 "GET /SOGo/so/user6@mydomain.net/Mail/view HTTP/1.0" 200 18835/0 0.080 82018 77% 2M
Apr 22 10:54:57 sogod [1552]: 192.168.0.2 "GET /SOGo/so/user6@mydomain.net/Calendar/alarmslist?browserTime=1587567297 HTTP/1.0" 200 63/0 0.005 - - 0
Apr 22 10:54:57 sogod [1552]: 192.168.0.2 "GET /SOGo/so/user6@mydomain.net/Mail/0/view HTTP/1.0" 200 3918/0 0.517 - - 0
Apr 22 10:55:00 sogod [1552]: 192.168.0.2 "POST /SOGo/so/user6@mydomain.net/Mail/0/folderINBOX/view HTTP/1.0" 200 26584/48 2.429 - - 16M
Apr 22 10:55:00 sogod [1552]: 192.168.0.2 "POST /SOGo/so/user6@mydomain.net/Mail/unseenCount HTTP/1.0" 200 21/31 0.342 - - 0
Apr 22 10:55:06 sogod [1552]: [ERROR] <0x0x5561f650c830[WOHttpTransaction]> client disconnected during delivery of response for <WORequest[0x0x5561f64edea0]: method=POST uri=/SOGo/so/user6@mydomain.net/Mail/0/folderINBOX/expunge app=SOGo rqKey=so rqPath=user6@mydomain.net/Mail/0/folderINBOX/expunge> (len=0): the socket was shutdown
Apr 22 10:55:06 sogod [1552]: 192.168.0.2 "POST /SOGo/so/user6@mydomain.net/Mail/0/folderINBOX/expunge HTTP/1.0" 204 0/0 0.338 - - 0
Apr 22 10:55:07 sogod [1552]: 192.168.0.2 "REPORT /SOGo/dav/user1%40mydomain.net/Calendar/personal/ HTTP/1.0" 207 125/188 0.007 - - 0
Apr 22 10:55:07 sogod [1552]: 192.168.0.2 "REPORT /SOGo/dav/user1%40mydomain.net/Calendar/personal/ HTTP/1.0" 207 125/188 0.007 - - 0
Apr 22 11:00:07 sogod [1552]: 192.168.0.2 "REPORT /SOGo/dav/user1%40mydomain.net/Calendar/personal/ HTTP/1.0" 207 125/188 0.022 - - 0
Apr 22 11:03:52 sogod [1552]: mx.mydomain.net "OPTIONS /SOGo/Microsoft-Server-ActiveSync HTTP/1.0" 200 0/0 0.002 - - 0

I just realized it could be a configuration issue. A very short while ago I did a ubuntu apt-get update where the upgrade stepped all over sogo's config file. I ended up restoring my old config file, uninstalling and re-installing sogo on top of that file. Is there a standard config file I can compare to?

Thanks for the help!

4 Reply by nowhere99 (edited by nowhere99 2020-04-23 02:30:58)

  • nowhere99
  • Member
  • Offline
  • Registered: 2017-11-10
  • Posts: 26

Re: Trouble connecting to EAS

OK I did a lot of testing with the domain and username settings in two email clients on Android, Bluemail and Vmware Boxer.  Most of the tweaks do not even trigger a user lookup in the MySQL DB. It looks like the clients can't seem to generate the correct domain/username combo to log in. The one setting that APPEARS to be the one that COULD generate the correct combo can't connect to the server for some reason.

Below are the domain and username settings I used in the clients and the lines they generated in the sogo.log file. There were no other log lines generated.  I've posted above all the lines generated prior to attempting a connection.

BTW, I cannot try to connect Outlook from windows at all since it doesn't let me edit any of the connection settings. I'm pretty sure it's forcing auto-discovery and there's no chance I've named my server what Outlook is expecting.

Gotta get this solved as I'm pretty much stuck without any contacts and calendar on my phone...

Bluemail Android Email Client
Domain\Username = user1@mydomain.net
Apr 22 13:31:53 sogod [9451]: |SOGo| starting method 'OPTIONS' on uri '/SOGo/Microsoft-Server-ActiveSync'
Apr 22 13:31:53 sogod [9451]: |SOGo| request took 0.001112 seconds to execute
Apr 22 13:31:53 sogod [9451]: mx.mydomain.net "OPTIONS /SOGo/Microsoft-Server-ActiveSync HTTP/1.0" 200 0/0 0.002 - - 0
Error: You typed an incorrect server address or the server requires a protocol that Email doesn't support

Domain\Username = mydomain.net\user1@mydomain.net
Apr 22 13:24:57 sogod [9451]: |SOGo| starting method 'OPTIONS' on uri '/SOGo/Microsoft-Server-ActiveSync'
Apr 22 13:24:57 sogod [9451]: |SOGo| request took 0.000964 seconds to execute
Apr 22 13:24:57 sogod [9451]: mx.mydomain.net "OPTIONS /SOGo/Microsoft-Server-ActiveSync HTTP/1.0" 200 0/0 0.002 - - 0
Error: You typed an incorrect server address or the server requires a protocol that Email doesn't support

Domain\Username = mydomain.net\user1
Apr 22 13:26:42 sogod [9451]: |SOGo| starting method 'OPTIONS' on uri '/SOGo/Microsoft-Server-ActiveSync'
2020-04-22 13:26:42.759 sogod[9451:9451] <MySQL4Channel[0x0x55743c9361c0] connection=0x0x55743cfbd8b0> SQL: SELECT c_password FROM users WHERE c_uid = 'user1';
2020-04-22 13:26:42.759 sogod[9451:9451] <MySQL4Channel[0x0x55743c9361c0] connection=0x0x55743cfbd8b0>   query has results, entering fetch-mode.
Apr 22 13:26:42 sogod [9451]: <0x0x55743cc97c60[SOGoDAVAuthenticator]> tried wrong password for user 'user1'!
Apr 22 13:26:42 sogod [9451]: |SOGo| request took 0.000924 seconds to execute
Apr 22 13:26:42 sogod [9451]: mx.mydomain.net "OPTIONS /SOGo/Microsoft-Server-ActiveSync HTTP/1.0" 401 12/0 0.002 - - 0
Error: Username or password is incorrect

Domain\Username = mydomain.net
Apr 22 13:28:02 sogod [9451]: |SOGo| starting method 'OPTIONS' on uri '/SOGo/Microsoft-Server-ActiveSync'
2020-04-22 13:28:02.985 sogod[9451:9451] <MySQL4Channel[0x0x55743c93af30] connection=0x0x55743cf6d6a0> SQL: SELECT c_password FROM users WHERE c_uid = 'mydomain.net';
2020-04-22 13:28:02.986 sogod[9451:9451] <MySQL4Channel[0x0x55743c93af30] connection=0x0x55743cf6d6a0>   query has results, entering fetch-mode.
Apr 22 13:28:02 sogod [9451]: <0x0x55743cc97c60[SOGoDAVAuthenticator]> tried wrong password for user 'mydomain.net'!
Apr 22 13:28:02 sogod [9451]: |SOGo| request took 0.001116 seconds to execute
Apr 22 13:28:02 sogod [9451]: mx.mydomain.net "OPTIONS /SOGo/Microsoft-Server-ActiveSync HTTP/1.0" 401 12/0 0.002 - - 0
Error: Username or password is incorrect

Boxer Android Email Client
Username = user1@mydomain.net, Domain = user1@mydomain.net, email address = user1@mydomain.net
no log entries made
Error: Can't connect to server

Username = user1@mydomain.net, Domain = mydomain.net, email address = user1@mydomain.net
Apr 22 13:37:28 sogod [9451]: |SOGo| starting method 'OPTIONS' on uri '/SOGo/Microsoft-Server-ActiveSync'
Apr 22 13:37:28 sogod [9451]: |SOGo| request took 0.001342 seconds to execute
Apr 22 13:37:28 sogod [9451]: mx.mydomain.net "OPTIONS /SOGo/Microsoft-Server-ActiveSync HTTP/1.0" 200 0/0 0.002 - - 0
Error: Can't connect to server

Username = user1@mydomain.net, Domain = mx.mydomain.net, email address = user1@mydomain.net
Apr 22 13:38:28 sogod [9451]: |SOGo| starting method 'OPTIONS' on uri '/SOGo/Microsoft-Server-ActiveSync'
Apr 22 13:38:28 sogod [9451]: |SOGo| request took 0.001060 seconds to execute
Apr 22 13:38:28 sogod [9451]: mx.mydomain.net "OPTIONS /SOGo/Microsoft-Server-ActiveSync HTTP/1.0" 200 0/0 0.002 - - 0
Error: Can't connect to server

Username = user1@mydomain.net, Domain = mydomain.net\user1@mydomain.net, email address = user1@mydomain.net
Apr 22 13:40:15 sogod [9451]: |SOGo| starting method 'OPTIONS' on uri '/SOGo/Microsoft-Server-ActiveSync'
2020-04-22 13:40:15.508 sogod[9451:9451] <MySQL4Channel[0x0x55743c7f7f50] connection=0x0x55743cf80ac0> SQL: SELECT c_password FROM users WHERE c_uid = 'user1@mydomain.net\user1@mydomain.net';
2020-04-22 13:40:15.509 sogod[9451:9451] <MySQL4Channel[0x0x55743c7f7f50] connection=0x0x55743cf80ac0>   query has results, entering fetch-mode.
Apr 22 13:40:15 sogod [9451]: <0x0x55743cc97c60[SOGoDAVAuthenticator]> tried wrong password for user 'user1@mydomain.net\user1@mydomain.net'!
Apr 22 13:40:15 sogod [9451]: |SOGo| request took 0.001028 seconds to execute
Apr 22 13:40:15 sogod [9451]: mx.mydomain.net "OPTIONS /SOGo/Microsoft-Server-ActiveSync HTTP/1.0" 401 12/0 0.002 - - 0
Error: Username or password is incorrect

Username = user1@mydomain.net, Domain = mydomain.net\, email address = user1@mydomain.net
Apr 22 13:42:24 sogod [9451]: |SOGo| starting method 'OPTIONS' on uri '/SOGo/Microsoft-Server-ActiveSync'
2020-04-22 13:42:24.466 sogod[9451:9451] <MySQL4Channel[0x0x55743c7f7f50] connection=0x0x55743cf80ac0> SQL: SELECT c_password FROM users WHERE c_uid = '\user1@mydomain.net';
2020-04-22 13:42:24.466 sogod[9451:9451] <MySQL4Channel[0x0x55743c7f7f50] connection=0x0x55743cf80ac0>   query has results, entering fetch-mode.
2020-04-22 13:42:24.467 sogod[9451:9451] <MySQL4Channel[0x0x55743c936150] connection=0x0x55743cfbd8b0> SQL: SELECT * FROM users WHERE (c_uid = '\user1@mydomain.net') OR (mail = '\user1@mydomain.net');
2020-04-22 13:42:24.467 sogod[9451:9451] <MySQL4Channel[0x0x55743c936150] connection=0x0x55743cfbd8b0>   query has results, entering fetch-mode.
Apr 22 13:42:24 sogod [9451]: |SOGo| request took 0.003176 seconds to execute
Apr 22 13:42:24 sogod [9451]: mx.mydomain.net "OPTIONS /SOGo/Microsoft-Server-ActiveSync HTTP/1.0" 200 0/0 0.004 - - 0
Error: Can't connect to server

UPDATE FYI: The one promising Bluemail entry that looks like it SHOULD generate the correct login combos produced this line in the ngnix log:

172.58.21.66 - mydomain.net\x5Cuser1@mydomain.net [22/Apr/2020:11:26:00 -0700] "OPTIONS /Microsoft-Server-ActiveSync HTTP/1.1" 200 0 "-" "BlueMail/9-EAS-2.0"

5 Reply by nowhere99

  • nowhere99
  • Member
  • Offline
  • Registered: 2017-11-10
  • Posts: 26

Re: Trouble connecting to EAS

roll

Um... OK. Embarrassing... sogo-activesync package was not installed. Good grief. It must have gotten purged a short while ago when I had the apt-get update issue that also stepped on my config file.

I can once again set up users with EAS.