appgini_query_log table???

Please report bugs and any annoyances here. Kindly include all possible details: steps to reproduce, expected result, actual result, screenshots, ... etc.
Post Reply
pfrumkin
Veteran Member
Posts: 147
Joined: 2020-02-18 17:58
Location: Albuquerque, New Mexico USA

appgini_query_log table???

Post by pfrumkin » 2021-08-17 16:19

Hi all,

I just noticed this table appgini_query_log. It seems to log internal SQL transactions, it is nothing I am doing (intentionally). This is using AG 5.97. My more mature app is still on 5.84 so perhaps this is a new feature in 5.97. The transactions look almost like there are some near infinite loops as many transactions happen at the same time, or perhaps this is some sort of attack. The transactions are ALTER TABLE on the membership_users and membership_userrecords tables, so really doesn't feel good. The result is an error for duplicate key or duplicate column.

Anyone know anything about it that they can share? I only noticed it because it caused serious database bloat - like my database backup was 57 MB and 56 MB were in this one table!

Thanks!

~Paul

peebee
AppGini Super Hero
AppGini Super Hero
Posts: 268
Joined: 2013-03-21 04:37

Re: appgini_query_log table???

Post by peebee » 2021-08-18 06:24

Must admit I hadn't noticed that table either until reading this?

Just checked the Change log for V5.97 and read this:
Add pageQueryLogs.php to view log of slow and error queries for debugging (Admin area > Utilties menu > Query logs)

Sounds like a good idea - although I see that table fills with Errors that I don't believe should be happening?

For example: In this app (which is not even being used yet and has 1 x Admin user only) - Guest access is disabled. These are the errors reported:
ag-screenshot.jpg
ag-screenshot.jpg (175.99 KiB) Viewed 537 times
Those errors were generated by simply doing noting other than loggin in as Admin and going directly to the Query logs in the Admin area.

Yes - I can see that table is going to grow to a colossal size in no time at all?

To make matters worse, unless I'm missing something there also doesn't seem to be any means by which to turn off the error reporting or for the Admin to clear the table within the App itself - other than truncating via phpmyadmin or similar?

Any further insights appreciated.

User avatar
jsetzer
AppGini Super Hero
AppGini Super Hero
Posts: 1152
Joined: 2018-07-06 06:03
Location: Kiel, Germany
Contact:

Re: appgini_query_log table???

Post by jsetzer » 2021-08-18 11:27

Hi,

I did a short research and I can confirm the problem. I have found the reason and a interim-solution which I have just emailed to Ahmed, hoping for a fast patch. I am going to explain the problem and provide a hotfix in here:

Hotfix for 5.97

Important: This hotfix will be overwritten :!: on next generation unless you protect that file before generation or auto-patch it after each generation.
  1. Open incFunctions.php in your code editor
  2. Search for the string
    /* log slow queries that take more than 1 sec */
    You should find that string inside the sql()-function which is widely used in the whole application.
  3. Within that function, find the line

    Code: Select all

    if ($t1 - $t0 > 1.0 && empty($o['noSlowQueryLog']))
    EHP9siDqCx.png
    EHP9siDqCx.png (20.6 KiB) Viewed 518 times
  4. Put additional round brackets around the statement $t1-$t0 like so: ($t1 - $t0)
    The full line should look like this now:

    Code: Select all

    if (($t1 - $t0) > 1.0 && empty($o['noSlowQueryLog']))
    Code_gPKkHFTAr1.png
    Code_gPKkHFTAr1.png (21.95 KiB) Viewed 518 times
  5. Save the file
-----

Reason

I may be wrong, but I think the reason is the following: Due to ranking of logic- and mathematical- operators in programming languages, comparison will be executed before mathematics. Here, the statement $t1 - $t0 > 1.0 wll be evaluated as $t1 - ($t0 > 1.0) (note the brackets).

$t0 and $t1 are microseconds. Their values will be somewhere greater than 1,629,284,638 nowadays.

This means $t0 will always be > 1, so the expression ($t0 > 1.0) evaluates to true. Being used in a mathematical expression, true will be evaluated as 1. So our condition reads $t1 - 1. As $t1 is much greater than 1, the result of expression $t1 - 1 is greater than one.

This means this whole expression will always return true. As a result, every query will be logged (unless you pass noSlowQueryLog to the $o parameter which you can do when using the sql-function by yourself, but you cannot do for all generated standard sql-function calls within the whole application).

-----

Tipp

If your table appgini_query_log has already grown, you can use this simple SQL command in yor database tool for quickly deleting all records.

Caution:
This will delete all (!) records from the table appgini_query_log. Be careful and don't forget your database backups. You have been warned!

:!: USE IT AT YOUR OWN RISK

Code: Select all

truncate table appgini_query_log
Kind regards,
<js />

pfrumkin
Veteran Member
Posts: 147
Joined: 2020-02-18 17:58
Location: Albuquerque, New Mexico USA

Re: appgini_query_log table???

Post by pfrumkin » 2021-08-18 20:56

Thank you both for your insights and feedback. I found that Query Log menu option and realized it was an AG feature, but good to know we're not being attacked. Thanks for that workaround Jan!

~Paul

peebee
AppGini Super Hero
AppGini Super Hero
Posts: 268
Joined: 2013-03-21 04:37

Re: appgini_query_log table???

Post by peebee » 2021-08-20 04:11

Thanks Jan for taking a look and your quick suggested fix.

Have to say though that I've applied your patch and it is not working for me? Identical errors still being registered in the Error log. Errors appear to be generated via the actual login process.

It's worth pointing out that these are DB insertions are being entered under the "Error" log rather than the "Slow Queries" log which I presume is related to the "function logErrorQuery($statement, $error) {" function in incFunctions.php rather than the function logSlowQuery - which your patch doesn't apply to?

Looks to me that this piece of code in incFuntions.php might possibly be the culprit - but how/why and how to fix I'm not sure

Code: Select all

$db_link = openDBConnection($o);

		/*
		 if openDBConnection() fails, it would abort execution unless 'silentErrors' is true,
		 in which case, we should return false from sql() without further action since
		 $o['error'] would be already set by openDBConnection()
		*/
		if(!$db_link) return false;

		$t0 = microtime(true);

		if(!$result = @db_query($statement, $db_link)) {
			if(!stristr($statement, "show columns")) {
				// retrieve error codes
				$errorNum = db_errno($db_link);
				$o['error'] = htmlspecialchars(db_error($db_link));

				if(empty($o['noErrorQueryLog']))
					logErrorQuery($statement, $o['error']);

				if(getLoggedAdmin())
					$o['error'] .= "<pre class=\"ltr\">{$Translation['query:']}\n" . htmlspecialchars($statement) . "</pre><p><i class=\"text-right\">{$Translation['admin-only info']}</i></p><p>{$Translation['try rebuild fields']}</p>";

				if($o['silentErrors']) return false;

				dieErrorPage($o['error']);
			}
		}
I thought it may be due to Guest access being disabled but I provided Guest access and it made no difference.

peebee
AppGini Super Hero
AppGini Super Hero
Posts: 268
Joined: 2013-03-21 04:37

Re: appgini_query_log table???

Post by peebee » 2021-08-20 04:26

And just to add to above report;

This error that is logged every time any User logs in is kind of disturbing?
ag-screenshot-2.jpg
ag-screenshot-2.jpg (82.57 KiB) Viewed 449 times
Full Error log:

Code: Select all

INSERT INTO `membership_users` SET 
			`memberID`='ACTUAL ADMIN USERNAME', 
			`passMD5`='ACTUAL HASHED ADMIN PASSWORD', 
			`email`='ACTUAL ADMIN EMAIL', 
			`signUpDate`='2021-08-20', 
			`groupID`='2', 
			`isBanned`=0, 
			`isApproved`=1, 
			`comments`='Admin member created automatically on 2021-08-20'
Error: Duplicate entry 'ACTUAL ADMIN USERNAME' for key 'PRIMARY'

And that Admin member was NOT automatically created on 2021-08-20 as that error log suggests

User avatar
jsetzer
AppGini Super Hero
AppGini Super Hero
Posts: 1152
Joined: 2018-07-06 06:03
Location: Kiel, Germany
Contact:

Re: appgini_query_log table???

Post by jsetzer » 2021-09-10 05:06

There are two kinds of log-entries:
  1. Errors
    Errors in SQL query or outdated database schema (difference(s) between configured model and actual database schema).
    Those will have an error message in "error" column.
  2. Slow SQL queries
    SQL queries which require more than 1.0 seconds for execution.
    Those should have a value > 0.2 in "duration" column.
I did not do any research on possibly false error-messages.

My post is related to slow-query entries. In my test database there here hundreds of entries having duration = 0.0. For me, those were false positives. I was trying to get rid of those. After applying my fix above and after truncating that table there were no more new false positives.
Kind regards,
<js />

peebee
AppGini Super Hero
AppGini Super Hero
Posts: 268
Joined: 2013-03-21 04:37

Re: appgini_query_log table???

Post by peebee » 2021-09-13 05:19

Thanks Jan. Yes, I realise there are both "Slow Query" and "Error" logs being recorded.

In my case - I don't actually have any Slow Queries, even without applying your fix. But I do have multiple and consistent Errors being reported.

The same Errors are reported at every login or page load of the Login page. All errors are identical and relate to "ALTER TABLE `membership_" (just like Paul reported in his original post on this thread) and each one of them relate to the User Admin only.

Errors are obviously being generated from these Update Membership functions "function update_membership_users()" in and above/below line 1367 of admin/incFunctions.php Why it is happening, I have no idea?

To test - I set up an absolute vanilla app with no edits, no plugins - nothing. 1 x table, 1 x field, 1 x User and 2 x User groups (Admin & Anon). Below is the error results?
Test-Error-Log.jpg
Test-Error-Log.jpg (122.17 KiB) Viewed 234 times
I've tried every User/group combination. Same errors remain?

Seems like merely reloading the login page causes the errors?? Any ideas why?

User avatar
jsetzer
AppGini Super Hero
AppGini Super Hero
Posts: 1152
Joined: 2018-07-06 06:03
Location: Kiel, Germany
Contact:

Re: appgini_query_log table???

Post by jsetzer » 2021-09-13 11:47

I can confirm this: I also get errors after logging in.

I have already sent a change request for not-logging avoidable errors (like errors on creating indexes which already exist) and feature requests for delete-all and delete buttons in admin backend to Ahmed a couple of days ago. Let's hope the amount of unnecessary error entries can be reduced in a first step.

As a workaround for now, if the amount gets critical or annoying, we could add some delete sql-commands for automatically deleting old entries, for example errors older than 30 days.
Kind regards,
<js />

User avatar
jsetzer
AppGini Super Hero
AppGini Super Hero
Posts: 1152
Joined: 2018-07-06 06:03
Location: Kiel, Germany
Contact:

Re: appgini_query_log table???

Post by jsetzer » 2021-09-13 12:23

In my environment there are about 15 new entries per login. I have added a small piece of code for automatically deleting logged error messages older than 1 day. This should keep the table small.

You can put something like this for example to login_ok()-function in hooks/__global.php

Code: Select all

// file: hooks/__global.php
function login_ok($memberInfo, &$args)
{
    $days = 1; $eo = null;
    sql("DELETE FROM `appgini_query_log` WHERE `error` IS NOT NULL AND date(`datetime`) < (curdate() - interval {$days} day)", $eo);
    return '';
}
PS: This will only delete errors but keep slow queries.
Kind regards,
<js />

peebee
AppGini Super Hero
AppGini Super Hero
Posts: 268
Joined: 2013-03-21 04:37

Re: appgini_query_log table???

Post by peebee » 2021-09-14 01:41

Just to add to your confirmation of the issue Jan....

I notice that those consistent 15 x ALTER and INSERT queries into the membership_xxx tables run BEFORE a successful login, not after.

Open a NEW browser window, load the login page (WITHOUT logging in) and those sql queries will run/errors will occur (tested via phpmyadmin)

Queries relate to the Super Admin user.

Think this is more than just avoidable errors that shouldn't be reported in the error log?

pfrumkin
Veteran Member
Posts: 147
Joined: 2020-02-18 17:58
Location: Albuquerque, New Mexico USA

Re: appgini_query_log table???

Post by pfrumkin » 2021-09-14 15:11

Oof, yes that is a design flaw. At a minimum there should be a flag to disable the logging.

Thanks peebee for this analysis and thanks again Jan for the next iteration of workaround.

~Paul

Post Reply