configuring Dovecot with wforced and auth_policy_server_url with https results in assertion failed
Robert Kudyba
rkudyba at fordham.edu
Fri Mar 29 16:28:47 EET 2019
>
> Well, as I said, it's up to squirrelmail to actually provide the real
> client IP. Otherwise dovecot cannot know it. You can try turning on imap
> rawlogs (see https://wiki.dovecot.org/Debugging/Rawlog
> <https://urldefense.proofpoint.com/v2/url?u=https-3A__wiki.dovecot.org_Debugging_Rawlog&d=DwMDaQ&c=aqMfXOEvEJQh2iQMCb7Wy8l0sPnURkcqADc2guUW8IM&r=X0jL9y0sL4r4iU_qVtR3lLNo4tOL1ry_m7-psV3GejY&m=tsGwDRgUrhwnh5KZlvG0kkoKFHTZ10ZLURcHI6mywak&s=23MOSSu15fdwptssjVJVkZk1TuC_hg3QMy5t_8nLFmw&e=>)
> and check if squirrelmail is forwarding client ip or not.
>
I added:to /etc/dovecot/conf.d/10-master.conf
service postlogin {
executable = script-login -d rawlog
unix_listener postlogin {
}
}
restarted Dovecot and wforce only seeing this, which shows the loopback
address:
*Mar 29 10:10:51 imap-login: Info: Login: user=<ouruser>, method=PLAIN,
rip=127.0.0.1, lip=127.0.0.1, mpid=10385, secured,
session=<8KTTPDyFVIh/AAAB>*
Mar 29 10:10:51 imap(ouruser)<10385><8KTTPDyFVIh/AAAB>: Info: Connection
closed (UID FETCH finished 0.030 secs ago) in=308 out=27743 deleted=0
expunged=0 trashed=0 hdr_count=50 hdr_bytes=10263 body_count=0 body_bytes=0
Mar 29 10:10:51 auth: Debug: auth client connected (pid=10389)
Mar 29 10:10:51 auth: Debug: client in: AUTH 1 PLAIN
service=imap secured session=2MwBPTyFWoh/AAAB lip=127.0.0.1
rip=127.0.0.1 lport=143 rport=34906 resp=<hidden>
Mar 29 10:10:51 auth: Debug: policy(ouruser,127.0.0.1,<2MwBPTyFWoh/AAAB>):
Policy request https://ourdomain:8084/?command=allow
Mar 29 10:10:51 auth: Debug: policy(ouruser,127.0.0.1,<2MwBPTyFWoh/AAAB>):
Policy server request JSON:
{"device_id":"","login":"ouruser","protocol":"imap","pwhash":"68","remote":"127.0.0.1","tls":false}
Mar 29 10:10:51 auth: Debug: http-client: peer ip.of.se.vr:8084 (shared):
Peer reused
Mar 29 10:10:51 auth: Debug: http-client[1]: queue https://ourdomain:8084:
Setting up connection to ip.of.se.vr:8084 (SSL=ourdomain) (2 requests
pending)
Mar 29 10:10:51 auth: Debug: http-client[1]: request [Req7: POST
https://ourdomain:8084/?command=allow]: Submitted (requests left=2)
Mar 29 10:10:51 auth: Debug: http-client[1]: peer ip.of.se.vr:8084:
Creating 1 new connections to handle requests (already 0 usable, connecting
to 0, closing 0)
Mar 29 10:10:52 auth: Debug: http-client: peer ip.of.se.vr:8084 (shared):
Backoff timer expired
Mar 29 10:10:52 auth: Debug: http-client[1]: peer ip.of.se.vr:8084: Making
new connection 1 of 1 (0 connections exist, 0 pending)
Mar 29 10:10:52 auth: Debug: http-client[1]: conn ip.of.se.vr:8084 [6]:
HTTPS connection created (1 parallel connections exist)
Mar 29 10:10:52 auth: Debug: http-client[1]: conn ip.of.se.vr:8084 [6]:
Connected
Mar 29 10:10:52 auth: Debug: http-client[1]: conn ip.of.se.vr:8084 [6]:
Starting SSL handshake
Mar 29 10:10:52 auth: Debug: http-client[1]: conn ip.of.se.vr:8084 [6]: SSL
handshake to ip.of.se.vr:8084 failed: Connection closed
Mar 29 10:10:52 auth: Debug: http-client[1]: peer ip.of.se.vr:8084:
Connection failed (1 connections exist, 0 pending)
Mar 29 10:10:52 auth: Debug: http-client: peer ip.of.se.vr:8084: Failed to
make connection (1 connections exist, 0 pending)
Mar 29 10:10:52 auth: Debug: http-client[1]: peer ip.of.se.vr:8084: Failed
to establish any connection within our peer pool: SSL handshake to
ip.of.se.vr:8084 failed: Connection closed (1 connections exist, 0 pending)
Mar 29 10:10:52 auth: Debug: http-client[1]: queue https://ourdomain:8084:
Failed to set up connection to ip.of.se.vr:8084 (SSL=ourdomain): SSL
handshake to ip.of.se.vr:8084 failed: Connection closed (1 peers pending, 2
requests pending)
Mar 29 10:10:52 auth: Debug: http-client: peer ip.of.se.vr:8084 (shared):
Peer reused
Mar 29 10:10:52 auth: Debug: http-client[1]: queue https://ourdomain:8084:
Setting up connection to ip.of.se.vr:8084 (SSL=ourdomain) (2 requests
pending)
Mar 29 10:10:52 auth: Debug: http-client[1]: queue https://ourdomain:8084:
Started new connection to ip.of.se.vr:8084 (SSL=ourdomain)
Mar 29 10:10:52 auth: Debug: http-client[1]: conn ip.of.se.vr:8084 [6]:
Connection close
Mar 29 10:10:52 auth: Debug: http-client[1]: conn ip.of.se.vr:8084 [6]:
Connection disconnect
Mar 29 10:10:52 auth: Debug: http-client[1]: conn ip.of.se.vr:8084 [6]:
Detached peer
Mar 29 10:10:52 auth: Debug: http-client[1]: conn ip.of.se.vr:8084 [6]:
Connection destroy
Mar 29 10:10:52 auth: Debug: http-client[1]: peer ip.of.se.vr:8084:
Creating 1 new connections to handle requests (already 0 usable, connecting
to 0, closing 0)
Mar 29 10:10:52 auth: Debug: http-client: peer ip.of.se.vr:8084 (shared):
Starting backoff timer for 6400 msecs
Mar 29 10:10:53 auth: Debug: http-client[1]: queue https://ourdomain:8084:
Timeout (now: 2019-03-29 10:10:53.503)
Mar 29 10:10:53 auth: Debug: http-client[1]: queue https://ourdomain:8084:
Absolute timeout expired for request [Req6: POST
https://ourdomain:8084/?command=report] (Request queued 2.001 secs ago, not
yet sent, 0.000 in other ioloops)
Mar 29 10:10:53 auth: Debug: http-client[1]: request [Req6: POST
https://ourdomain:8084/?command=report]: Error: 9008 Absolute request
timeout expired (Request queued 2.001 secs ago, not yet sent, 0.000 in
other ioloops)
Mar 29 10:10:53 auth: Debug: http-client[1]: queue https://ourdomain:8084:
Dropping request [Req6: POST https://ourdomain:8084/?command=report]
Mar 29 10:10:53 auth: Error: policy(ouruser,127.0.0.1,<8KTTPDyFVIh/AAAB>):
Policy server HTTP error: Absolute request timeout expired (Request queued
2.001 secs ago, not yet sent, 0.000 in other ioloops)
Mar 29 10:10:53 auth: Debug: http-client[1]: request [Req6: POST
https://ourdomain:8084/?command=report]: Destroy (requests left=2)
Mar 29 10:10:53 auth: Debug: http-client[1]: request [Req6: POST
https://ourdomain:8084/?command=report]: Free (requests left=1)
Mar 29 10:10:53 auth: Debug: http-client[1]: queue https://ourdomain:8084:
New timeout
Mar 29 10:10:53 auth: Debug: http-client[1]: queue https://ourdomain:8084:
Set request timeout to 2019-03-29 10:10:53.613 (now: 2019-03-29
10:10:53.503)
Mar 29 10:10:53 auth: Debug: http-client[1]: queue https://ourdomain:8084:
Timeout (now: 2019-03-29 10:10:53.613)
Mar 29 10:10:53 auth: Debug: http-client[1]: queue https://ourdomain:8084:
Absolute timeout expired for request [Req7: POST
https://ourdomain:8084/?command=allow] (Request queued 2.000 secs ago, not
yet sent, 0.000 in other ioloops)
What feature or setting would I be looking for in Squirrelmail to change to
wforce?
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://dovecot.org/pipermail/dovecot/attachments/20190329/9c153ae0/attachment-0001.html>
More information about the dovecot
mailing list