Something is continually trying to login to the database as root and being denied, filling the logs with 'access denied' entries. This appears to be happening every 30 seconds and can be viewed with docker logs hashtags_db_1.
I'm not sure why this is but we should stop whatever is doing it.
Can you paste the relevant excerpt from the log? Also, do you have an idea as to what is triggering this (e.g. viewing pages, editing pages, etc.)? Thanks.
2019-02-21T16:38:43.676509Z 27866 [Note] Access denied for user 'root'@'localhost' (using password: NO)
Looks to be happening every 30 seconds.
I wonder how we're going to track this down. I tried doing searches for 'root' and "root" but I don't see anything that looks relevant (just job queue stuff, collation stuff, preprocessor stuff, etc. referring to a root node). Is there a database function somewhere that handles logins?
Also, could it be that an extension is causing this?
Hard to say. The issue appears to be from within the db app itself since the connections are coming from localhost. I also double checked closing both the app and scripts containers and the spam continues.
I had a hunch that I think I've confirmed - the culprit appears to be the healthcheck at https://github.com/Samwalton9/hashtags/blob/master/docker-compose.yml#L25. I'd appreciate someone else double checking, but I removed the healthcheck and app dependency from docker-compose.yml, and ran docker-compose up -d --build again. Didn't see any of these logs without the healthcheck.
That check was added in T207277.
I'll leave it to you to figure out how we can still smoothly bring the containers, whether using that health check or another, while avoiding this log spam :)
@Samwalton9 i also had the same doubt, that healthcheck is the only thing which is running periodically.
We can show a warning to user if db can not be connected and exit the container
That's the default behaviour when containers are brought up - the app and scripts containers will exit with an error because the db container is still starting up. The healthcheck allows the app container to double check it can connect to the db (i.e. it's finished setup) before running. I'd like to keep that smooth behaviour.
@gaurav7019 The first step would be setting the tool up locally and confirming that you see the same behaviour. The repo can be found at https://github.com/samwalton9/hashtags.
Once you've reproduced the issue, I'd appreciate you double checking my suspicion above, that the cause is the linked health check. Once we've spent more time confirming the root cause we can discuss potential solutions.
The mistake in the code is very small, but to track it back, it seemed like a good experience. So, I am sharing my backstage work on this bug.
I reproduced the bug in the first installation, I think everybody noticed it in theirs.
2019-03-08T10:58:28.464252166Z 2019-03-08T10:58:28.464141Z 3 [Note] Access denied for user 'root'@'localhost' (using password: NO) 2019-03-08T10:58:58.615079992Z 2019-03-08T10:58:58.614883Z 5 [Note] Access denied for user 'root'@'localhost' (using password: NO) 2019-03-08T10:59:28.786614766Z 2019-03-08T10:59:28.786482Z 6 [Note] Access denied for user 'root'@'localhost' (using password: NO) 2019-03-08T10:59:58.893507819Z 2019-03-08T10:59:58.893398Z 7 [Note] Access denied for user 'root'@'localhost' (using password: NO)
I started working on this, the logs are weird as we aren't making any connection every 30s or so, with an empty password. At first I thought it is some code error, I did pattern matching in the code base to find where are we actually doing mysql connection without password. But, it was not helpful. It seemed to be little tricky.
So, I went little deep and as the error log suggests, its from user root and host localhost. That means the request might come from the following,
To find out what it actually is, I checked tcpdump on port 3306 and I was very surprised to see that, even though there is no tcpdump log the Access denied for user 'root'@'localhost' (using password: NO) log keeps appearing.
So, the 2nd and 3rd options are ruled out. And the 1st option is partially ruled out as there is no tcp request in the interface lo. If its not from tcp, then there is something which is directly operating on the socket file of mysql i.,e /var/run/mysqld/mysqld.sock.
I went forward to the code base again and I actually need to look into docker-compose.yml only as there is no code running in the hashtags_db_1 container(confirmed this with htop in the container), and finally figured out that, it is because of the health checkup we put for the same container, i.e, the following code,
healthcheck:
test: ["CMD", "mysqladmin", "ping", "-h", "localhost"]
timeout: 20s
retries: 10So, what actually happening is, healthcheck is running in the background and as we didn't provided password for the mysqladmin it tried with empty password causing those logs.
One thing we can notice is healthcheck is tagging the container healthy even though there is mysql error in it (Empty password).
To fix this, I changed it to the following,
healthcheck: test: ["CMD", "mysqladmin", "ping", "-h", "localhost", "-phashtag"] timeout: 20s
I am making a PR to fix this.