Fix error logging to be less noisy for port scans

[david-watson]

Deployed latest glutton on a Digital Ocean droplet (no docker) and ran basic nmap scan (all TCP ports). Would expect to see the results as all ports open, but some ports did not respond and many "use of closed network connection" errors were logged:

user@n.n.n.n:~$ nmap g.g.g.g

Starting Nmap 6.40 ( http://nmap.org ) at 2017-11-17 04:46 GMT
Nmap scan report for g.g.g.g
Host is up (0.18s latency).
PORT      STATE    SERVICE
1/tcp     open     tcpmux
3/tcp     open     compressnet
4/tcp     open     unknown
6/tcp     open     unknown
7/tcp     open     echo
9/tcp     open     discard
13/tcp    open     daytime
17/tcp    open     qotd
19/tcp    open     chargen
20/tcp    open     ftp-data
21/tcp    open     ftp
22/tcp    open     ssh
23/tcp    open     telnet
24/tcp    open     priv-mail
25/tcp    open     smtp
26/tcp    open     rsftp
30/tcp    open     unknown
...

Logs:

2017/11/17 04:47:17 ERROR user.tcp: close tcp g.g.g.g:5000->n.n.n.n:40613: use of closed network connection
2017/11/17 04:47:17 ERROR user.tcp: close tcp g.g.g.g:5000->n.n.n.n:50191: use of closed network connection
2017/11/17 04:47:17 ERROR user.tcp: close tcp g.g.g.g:5000->n.n.n.n:56103: use of closed network connection
2017/11/17 04:47:17 ERROR user.tcp: close tcp g.g.g.g:5000->n.n.n.n:56748: use of closed network connection
2017/11/17 04:47:17 ERROR user.tcp: close tcp g.g.g.g:5000->n.n.n.n:35219: use of closed network connection
2017/11/17 04:47:17 ERROR user.tcp: close tcp g.g.g.g:5000->n.n.n.n:37463: use of closed network connection
2017/11/17 04:47:17 ERROR user.tcp: close tcp g.g.g.g:5000->n.n.n.n:50858: use of closed network connection
2017/11/17 04:47:17 ERROR user.tcp: close tcp g.g.g.g:5000->n.n.n.n:41272: use of closed network connection

[glaslos]

Did we confirm that you will get all ports when specifying the range?

[kung-foo]

might be worth making a system test via Docker

[david-watson]

Default nmap scans top 1000 ports, so no ports missed, but a lot of errors in the logs

[kung-foo]

probably comes from: https://github.com/kung-foo/freki/blob/master/userconnhandler_tcp.go#L45

[glaslos]

Updated title to reflect feedback

[t3chn0m4g3]

I have a comparable situation which I think might be related to new connections / drops in normal operation (no portscan). For every connection attempt I am getting a ...

{"level":"info","ts":1523885848.9937115,"caller":"glutton/system.go:34","msg":"[system  ] running Go routines: 16 and open files: 9","sensorID":"ce2600c6-62dd-47e8-b4cd-507e83081847"}

... even if debug is set to false.

Is there an easy way to tune that down or just log [log.tcp ]-related events?

[glaslos]

You want to change this line: https://github.com/mushorg/glutton/blob/master/system.go#L34

[t3chn0m4g3]

@glaslos Thank you, just got rid of ...

			case <-ticker.C:
				openFiles := countOpenFiles()
				runningRoutines := countRunningRoutines()
				g.logger.Info(fmt.Sprintf("[system  ] running Go routines: %d and open files: %d",
					openFiles, runningRoutines))

... and the log file is finally quiet when nothing is going on.

[glaslos]

You could also change g.logger.Info to g.logger.Debug and set Gluttons log level to info.

[glaslos]

@t3chn0m4g3 do you want to try to reproduce this with the switch to TPROXY?