Bug 16734 - ufdbguard does not work with squid 3.4
Summary: ufdbguard does not work with squid 3.4
Status: RESOLVED FIXED
Alias: None
Product: Mageia
Classification: Unclassified
Component: RPM Packages (show other bugs)
Version: 5
Hardware: i586 Linux
Priority: Normal critical
Target Milestone: ---
Assignee: QA Team
QA Contact:
URL:
Whiteboard: has_procedure advisory MGA5-32-OK mga...
Keywords: validated_update
Depends on:
Blocks:
 
Reported: 2015-09-10 20:31 CEST by David Walser
Modified: 2015-09-18 17:58 CEST (History)
1 user (show)

See Also:
Source RPM: ufdbguard-1.31-5.mga5.src.rpm
CVE:
Status comment:


Attachments

Description David Walser 2015-09-10 20:31:19 CEST
The version of ufdbguard does not work with Squid 3.4 (at least redirection of HTTPS URLs doesn't), the version of Squid that we shipped with Mageia 5.  Upstream released an update to fix this:
https://www.urlfilterdb.com/release-1.31.html

Updated packages uploaded for Mageia 5 and Cauldron.

Advisory:
----------------------------------------

The ufdbguard package has been updated to version 1.31-patch13, which fixes an
incompatibility with Squid 3.4 and several other bugs.  See the upstream
release notes for more details.

References:
https://www.urlfilterdb.com/release-1.31.html
----------------------------------------

Updated packages in core/updates_testing:
----------------------------------------
ufdbguard-1.31-5.1.mga5
ufdbguard-cgi-1.31-5.1.mga5

from ufdbguard-1.31-5.1.mga5.src.rpm

Reproducible: 

Steps to Reproduce:
Comment 1 David Walser 2015-09-10 20:33:21 CEST
The README.urpmi file tells you what you need to add to squid.conf for it to use ufdbguard (then make sure you reload or restart the squid service).  When I tested it, browsing to http://www.doubleclick.net/ came up as blocked, and https://www.doubleclick.net/ gave me the "It works!" page from the system's local Apache server.  Tested Mageia 5 i586 locally.

Whiteboard: (none) => has_procedure MGA5-32-OK

Comment 2 claire robinson 2015-09-18 09:52:46 CEST
After installing the update with ufdb service started and confirmed working ok the ufdb service is stopped. Logs in /var/log/ufdb have all been emptied, zero bytes.

It's strange as squid shows ufdbclient processes attached and ps shows in fact they are still running, but..

# systemctl status ufdb.service 
â ufdb.service - LSB: ufdbguardd daemons from URLfilterDB
   Loaded: loaded (/etc/rc.d/init.d/ufdb)
   Active: inactive (dead)

After restarting squid it shows ufdbguard still running but no child processes and still nothing in ufdb logs.

# ps aux | grep ufdb
squid    14231  0.0  0.1 2093108 11708 ?       Ssl  08:38   0:00 /usr/bin/ufdbguardd -U squid -c /etc/ufdb/ufdbGuard.conf
squid    14320  0.0  0.0   8752  1556 ?        S    08:38   0:00 /usr/bin/ufdbhttpd -p 8080 -l /var/log/ufdb -I /usr/share/ufdbGuard/images -i 127.0.0.1 -U squid

Restarting ufdb..

# systemctl start ufdb.service 
# systemctl status ufdb.service 
â ufdb.service - LSB: ufdbguardd daemons from URLfilterDB
   Loaded: loaded (/etc/rc.d/init.d/ufdb)
   Active: active (exited) since Fri 2015-09-18 08:50:53 BST; 4s ago
  Process: 15281 ExecStart=/etc/rc.d/init.d/ufdb start (code=exited, status=0/SUCCESS)

Sep 18 08:50:53 mega ufdb[15281]: Starting URLfilterDB daemons OK
Sep 18 08:50:53 mega ufdb[15281]: FATAL ERROR: cannot read from "/usr/share/ufdbGuard/db/entertainment/domains.ufdb...  *****
Sep 18 08:50:53 mega ufdb[15281]: FATAL ERROR: cannot read from "/usr/share/ufdbGuard/db/proxies/domains.ufdb" (rea...  *****
Sep 18 08:50:54 mega ufdb[15281]: FATAL ERROR: cannot bind daemon socket: Address already in use (protocol=UNIX)  *****
Sep 18 08:50:54 mega ufdb[15281]: cannot bind daemon socket: Address already in use (protocol=UNIX) *****
Sep 18 08:50:54 mega ufdb[15281]: check for and kill old daemon processes
Sep 18 08:50:54 mega ufdb[15281]: and remove UNIX socket file "/tmp/ufdbguardd-03977"

Whiteboard: has_procedure MGA5-32-OK => has_procedure feedback MGA5-32-OK

Comment 3 claire robinson 2015-09-18 10:01:57 CEST
After restarting squid there are now ufdb logs. Tested with facebook.com which was blocked by this as entertainment, and is still inaccessible with the update applied.

/var/log/ufdb/ufdbguardd.log starts with..

2015-09-18 08:50:53 [15285] FATAL ERROR: cannot read from "/usr/share/ufdbGuard/db/entertainment/domains.ufdb" (read-only): N
o such file or directory  *****
2015-09-18 08:50:53 [15285] loading URL table from "/usr/share/ufdbGuard/db/entertainment/domains"
2015-09-18 08:50:53 [15285] ERROR: URL database table "/usr/share/ufdbGuard/db/entertainment/domains" is empty and is ignored
   *****
2015-09-18 08:50:53 [15285] FATAL ERROR: cannot read from "/usr/share/ufdbGuard/db/proxies/domains.ufdb" (read-only): No such
 file or directory  *****
2015-09-18 08:50:53 [15285] loading URL table from "/usr/share/ufdbGuard/db/proxies/domains"
2015-09-18 08:50:53 [15285] ERROR: URL database table "/usr/share/ufdbGuard/db/proxies/domains" is empty and is ignored   ***
**


and ends with


2015-09-18 08:50:53 [15285] configuration status: fatal error(s)
2015-09-18 08:50:53 [15285]  
2015-09-18 08:50:53 [15285] using OpenSSL library 1.0.2d R (OpenSSL 1.0.2d 9 Jul 2015)
2015-09-18 08:50:53 [15285] HTTPS/SSL verification with trusted certificates from file "/usr/share/ufdbGuard/db/security/cacerts" and directory "none"
2015-09-18 08:50:53 [15285] 32 HTTPS verification threads created.
2015-09-18 08:50:54 [15285] ERROR: A FATAL ERROR OCCURRED: ALL REQUESTS ARE ANSWERED WITH "OK" (see previous lines for more information)  *****
2015-09-18 08:50:54 [15285] Changing daemon status to "error"
2015-09-18 08:50:54 [15285] FATAL ERROR: cannot bind daemon socket: Address already in use (protocol=UNIX)  *****
2015-09-18 08:50:54 [15285] check for and kill old daemon processes
2015-09-18 08:50:54 [15285] and remove UNIX socket file "/tmp/ufdbguardd-03977"
2015-09-18 08:50:55 [15285] Changing daemon status to "terminated"
2015-09-18 08:50:55 [15285] ufdbGuard daemon stopped
Comment 4 claire robinson 2015-09-18 10:13:33 CEST
Stopped both squid and ufdb, then started squid and ufdb in that order.

Squid shows..

# systemctl status squid.service -l
â squid.service - LSB: Starts the squid daemon
   Loaded: loaded (/etc/rc.d/init.d/squid)
   Active: active (running) since Fri 2015-09-18 09:03:24 BST; 3min 57s ago
  Process: 16045 ExecStop=/etc/rc.d/init.d/squid stop (code=exited, status=0/SUCCESS)
  Process: 16154 ExecStart=/etc/rc.d/init.d/squid start (code=exited, status=0/SUCCESS)
 Main PID: 16172 (squid)
   CGroup: /system.slice/squid.service
           ââ16170 squid
           ââ16172 (squid-1)
           ââ16174 (logfile-daemon) /var/log/squid/access.log
           ââ16175 (pinger)
           ââ16383 (ufdbgclient) -l /var/log/ufdb

Sep 18 09:03:23 mega squid[16165]: Squid Parent: will start 1 kids
Sep 18 09:03:23 mega squid[16165]: Squid Parent: (squid-1) process 16168 started
Sep 18 09:03:23 mega squid[16165]: Squid Parent: (squid-1) process 16168 exited with status 0
Sep 18 09:03:23 mega squid[16170]: Squid Parent: will start 1 kids
Sep 18 09:03:23 mega squid[16170]: Squid Parent: (squid-1) process 16172 started
Sep 18 09:03:24 mega squid[16154]: init_cache_dir ... Starting squid: .[  OK  ]
Sep 18 09:03:24 mega systemd[1]: squid.service: Supervising process 16172 which is not our child. We'll most likely not notice when it exits.

ufdb shows..
# systemctl status ufdb.service  -l
â ufdb.service - LSB: ufdbguardd daemons from URLfilterDB
   Loaded: loaded (/etc/rc.d/init.d/ufdb)
   Active: active (running) since Fri 2015-09-18 09:03:29 BST; 2min 45s ago
  Process: 16098 ExecStop=/etc/rc.d/init.d/ufdb stop (code=exited, status=0/SUCCESS)
  Process: 16206 ExecStart=/etc/rc.d/init.d/ufdb start (code=exited, status=0/SUCCESS)
   CGroup: /system.slice/ufdb.service
           ââ16210 /usr/bin/ufdbguardd -U squid -c /etc/ufdb/ufdbGuard.conf
           ââ16320 /usr/bin/ufdbhttpd -p 8080 -l /var/log/ufdb -I /usr/share/ufdbGuard/images -i 127.0.0.1 -U squid

Sep 18 09:03:29 mega ufdb[16206]: Starting URLfilterDB daemons OK
Sep 18 09:03:30 mega ufdb[16206]: FATAL ERROR: cannot read from "/usr/share/ufdbGuard/db/entertainment/domains.ufdb" (read-only): No such file or directory  *****
Sep 18 09:03:30 mega ufdb[16206]: FATAL ERROR: cannot read from "/usr/share/ufdbGuard/db/proxies/domains.ufdb" (read-only): No such file or directory  *****

# ll /usr/share/ufdbGuard/db/
total 20
drwxr-xr-x 2 root root 4096 Sep 18 08:42 entertainment/
drwxr-xr-x 2 root root 4096 Sep 18 08:42 ipv6/
drwxr-xr-x 2 root root 4096 Sep 18 08:42 known/
drwxr-xr-x 2 root root 4096 Sep 18 08:42 proxies/
drwxr-xr-x 2 root root 4096 Sep 18 08:42 security/

# ll /usr/share/ufdbGuard/db/proxies/
total 16
-rw-r--r-- 1 root root   72 Apr 13  2012 domains
-rw-r--r-- 1 root root  187 Aug 20  2010 expressions
-rw-r--r-- 1 root root  187 Dec  7  2006 expressions.proxies.default
-rw-r--r-- 1 root root 2318 Aug 20  2010 expressions.test.many
-rw-r--r-- 1 root root    0 Dec  7  2006 urls

# ll /usr/share/ufdbGuard/db/entertainment/
total 4
-rw-r--r-- 1 root root 110 Aug  3  2010 domains



Facebook is now accessible..

/var/log/ufdb/ufdbguardd.log shows..

2015-09-18 09:03:30 [16210] ufdbguardd 1.31 started with 65 URL verification threads and 32 SSL verification threads
2015-09-18 09:03:30 [16210] raising privileges to start ufdbhttpd
2015-09-18 09:03:30 [16210] starting HTTP daemon ...
2015-09-18 09:03:30 [16210] dropped privileges and became user 'squid'
2015-09-18 09:03:30 [16210] ufdbhttpd is started.  port=8080 interface=127.0.0.1 images=/usr/share/ufdbGuard/images
2015-09-18 09:04:23 [16210] PASS  -           mega config     fatal-error facebook.com:443 CONNECT
2015-09-18 09:04:23 [16210] PASS  -           mega config     fatal-error http://ocsp.digicert.com/ POST
2015-09-18 09:04:23 [16210] PASS  -           mega config     fatal-error www.facebook.com:443 CONNECT
2015-09-18 09:04:23 [16210] PASS  -           mega config     fatal-error static.xx.fbcdn.net:443 CONNECT
2015-09-18 09:04:23 [16210] PASS  -           mega config     fatal-error static.xx.fbcdn.net:443 CONNECT
Comment 5 claire robinson 2015-09-18 10:15:38 CEST
Should mention that I'd enabled the logging in /etc/ufdb/ufdbGuard.conf
Comment 6 David Walser 2015-09-18 12:35:15 CEST
Run:
/usr/bin/ufdbConvertDB /usr/share/ufdbGuard/db/

Note that those categories are just examples, normally you'd make your own, download some other ones, or buy the ones from upstream.

The correct order to start the services is ufdb and squid.  The information in the ufdb init script takes care of this if you have both enabled when you boot.

Whiteboard: has_procedure feedback MGA5-32-OK => has_procedure MGA5-32-OK

Comment 7 claire robinson 2015-09-18 12:38:43 CEST
That apparently never happened then, as the update broke the installed working filter.
Comment 8 David Walser 2015-09-18 12:42:34 CEST
(In reply to claire robinson from comment #7)
> That apparently never happened then, as the update broke the installed
> working filter.

You started the services in the wrong order.  That's the behavior when that happens.  It's documented in the manual.
Comment 9 claire robinson 2015-09-18 12:45:26 CEST
No, you're misunderstanding. All I did was update the ufdbguard packages. The rest was debugging.
Comment 10 David Walser 2015-09-18 12:51:51 CEST
If you start the services in the correct order, it works, I promise you.  Yes, if you replace the ufdbguard with a newer version, it will have to restart, so squid has to then be restarted.  It doesn't shut down the proxy, it just "fails open," as described in the manual.  The previous version doesn't totally work correctly anyway, hence the reason for this update.  The updated version does work.  It's a complicated piece of software and to get optimal behavior for a specific use case, it's best to read the manual, but just for basic demonstration operation, it does work out of the box.  It's behaving as it's intended to.
Comment 11 claire robinson 2015-09-18 13:12:29 CEST
I'm not convinced it's fully correct, but I'll OK it. We've not updated this one before.

The ufdb service restarting on update appears to upset the start sequence of squid/ufdb. It perhaps needs to stop and restart both services in the correct order instead of just itself.

For future testers:

Install with squid and with both services stopped.

Edit /etc/ufdb/ufdbGuard.conf and enable the logging by changing the Off's to On's.

Edit /etc/squid/squid.conf and add the two lines from README.urpmi ..
url_rewrite_program /usr/bin/ufdbgclient -l /var/log/ufdb
url_rewrite_children 64

Start ufdb service and verify it's running, then start squid service and verify it is running too.

Set your browser to use a proxy of localhost:3128 and browse as normal, try doubleclick.net or facebook.com and they should be blocked.

Check logs in /var/log/ufdb/ and /var/log/squid/

Apply the update and notice ufdb service is now stopped.

Stop squid service too.

Restart ufdb and then squid services and test again.

Remember to reset your browser proxy settings back to normal.

Whiteboard: has_procedure MGA5-32-OK => has_procedure MGA5-32-OK mga5-64-ok

claire robinson 2015-09-18 13:18:12 CEST

Keywords: (none) => validated_update
CC: (none) => sysadmin-bugs

Comment 12 David Walser 2015-09-18 13:20:46 CEST
(In reply to claire robinson from comment #11)
> I'm not convinced it's fully correct, but I'll OK it. We've not updated this
> one before.
> 
> The ufdb service restarting on update appears to upset the start sequence of
> squid/ufdb. It perhaps needs to stop and restart both services in the
> correct order instead of just itself.

Yes, I think you're right.  One has to restart squid manually after installing this update.  That's not ideal, but the way it's designed to fail open makes it not the end of the world.  Fortunately I wouldn't expect to have to update this package very often, this was just an unusual case where the version we released with Mageia 5 was (at least partially) broken with the Squid version we shipped, so we had to update it to a working version.  I have in mind a potential solution to making it restart Squid after updating itself, but I don't think it will work in Mageia 5 due to a systemd bug there (already filed elsewhere in Bugzilla).  I'll give it a shot in Cauldron though, so perhaps we can definitively avoid this issue in the future.  I wish it wasn't so finnicky about the start order, but that's a product of the way ufdbguard was designed.  Thanks for validating and for your careful testing.
Comment 13 claire robinson 2015-09-18 16:56:41 CEST
Thanks David. Bug 16777 created for that.

Advisory uploaded.

Whiteboard: has_procedure MGA5-32-OK mga5-64-ok => has_procedure advisory MGA5-32-OK mga5-64-ok

Comment 14 Mageia Robot 2015-09-18 17:58:18 CEST
An update for this issue has been pushed to Mageia Updates repository.

http://advisories.mageia.org/MGAA-2015-0129.html

Status: NEW => RESOLVED
Resolution: (none) => FIXED


Note You need to log in before you can comment on or make changes to this bug.