[MXS-1719] masking filter with readwritesplit router problems Created: 2018-03-15  Updated: 2020-08-27  Resolved: 2020-08-27

Status: Closed
Project: MariaDB MaxScale
Component/s: masking, readwritesplit
Affects Version/s: 2.2.2
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Zeve Assignee: Johan Wikman
Resolution: Cannot Reproduce Votes: 0
Labels: None
Environment:

1 maxscale, 1 master & 1 slave

Issue Links:
Relates
relates to MXS-1920 # is not recognized as an until-end-... Closed
relates to MXS-1861 masking filter logs warnings with mul... Closed
Sprint: MXS-SPRINT-54, MXS-SPRINT-58, MXS-SPRINT-59, MXS-SPRINT-60, MXS-SPRINT-61, MXS-SPRINT-62, MXS-SPRINT-63

 Description   

When using the masking filter together with a *readwritesplit * router for basic queries/inserts it works; the same goes when doing normal inserts from CLI or phpmyadmin. However, when using the application and doing complex inserts, i get the following message:

2018-03-15 14:08:27   info   : (64) [readwritesplit] Route query to master      [db01]:3306 <
 
2018-03-15 14:08:27   warning: (64) [masking] Received data, although expected nothing.
 
2018-03-15 14:08:27   warning: (64) [masking] Received data, although expected nothing.
 
2018-03-15 14:08:27   warning: (64) [masking] Received data, although expected nothing.
 
2018-03-15 14:08:27   warning: (64) [masking] Received data, although expected nothing.
 
2018-03-15 14:08:27   warning: (64) [masking] Received data, although expected nothing.

and the application hangs, no other error messages (log-info is enabled).

I cannot find anything related to this message. Is there any limitation when combining readwritesplit router and the masking filter? It manifests the same behavior even with only one server (when the slave is down).

Here are the masking and service configurations:

[Mask-Users]
 
type=filter
 
module=masking
 
warn_type_mismatch=always
 
rules=/etc/maxscale.modules.d/mask-users.json
 
 
 
[R/W-Service]
 
type=service
 
router=readwritesplit
 
servers=db01,db02
 
user=maxscale
 
passwd=XXXXXXX
 
max_slave_connections=100%
 
filters=Mask-Users

Here are a part of the masking rules, they just repeat for different databases and more columns...I masked some db_names/user due to my company privacy issues:

{
 
    "rules": [
 
        {
 
            "replace": {
 
                "database": "documentsdev",
 
                "column": "aa_label"
 
            },
 
            "with": {
 
                "fill": "*"
 
            },
 
            "applies_to": ["dev_user1", "dev_user2", "dev_user3", "dev_user4"]
 
        },
 
        {
 
            "replace": {
 
                "database": "documentsdev",
 
                "column": "al_diff"
 
            },
 
            "with": {
 
                "fill": "*"
 
            },
 
            "applies_to": ["dev_user1", "dev_user2", "dev_user3", "dev_user4"]
 
        },
 
        {
 
            "replace": {
 
                "database": "documentsdev",
 
                "column": "al_username"
 
            },
 
            "with": {
 
                "fill": "*"
 
            },
 
            "applies_to": ["dev_user1", "dev_user2", "dev_user3", "dev_user4"]
 
        },
 
        {
 
            "replace": {
 
                "database": "documentsdev",
 
                "column": "ar_u_username"
 
            },
 
            "with": {
 
                "fill": "*"
 
            },
 
            "applies_to": ["dev_user1", "dev_user2", "dev_user3", "dev_user4"]
 
        }
 
    ]
 
}

The masking filter applies to a small list of users, which are different than the users under which the application runs.

However when using the masking filter with the *readconnroute * router, everything works fine.

___________________________
UPDATE:
It does the same with only 1 simple rule:

{
 
    "rules": [
 
        {
 
            "replace": {
 
                "database": "documentsdev",
 
                "column": "aa_label"
 
            },
 
            "with": {
 
                "fill": "*"
 
            },
 
            "applies_to": ["dev_user1", "dev_user2", "dev_user3", "dev_user4"]
 
        }
 
    ]
 
}

And the above rule is for a different database

 Comments   
Comment by Johan Wikman [ 2018-03-15 ]

Could you provide your masking rules and an example of a problematic complex insert?

Comment by Zeve [ 2018-03-15 ]

@Johan.wikman

I updated the rules info, however I cannot post the whole query as it contains company sensitive data. (I have the full info logs from maxscale; is there a way to send them secure?)

Comment by Johan Wikman [ 2018-03-16 ]

zeve You can upload stuff to ftp://ftp.mariadb.com/uploads

Then please notify me at johan.wikman@mariadb.com when you have uploaded the log and what the filename is.

Comment by Zeve [ 2018-03-16 ]

@Johan Wikman , I uploaded the files and sent you an email.

Comment by Johan Wikman [ 2018-03-16 ]

zeveThank you, I have the zip-file now and will start investigating.

Comment by Johan Wikman [ 2018-03-16 ]

zeve I managed to reproduce the problem. It's related to multi-statements. If you can somehow prevent the client from using multi-statements then it probably would work. We'll fix it properly but cannot yet say when the fix will be available.

Comment by Zeve [ 2018-03-19 ]

Hi Johan,

Thank you for the investigation! As our application is a bit complex, we cannot use simple-statements, so we will have to use a write-only service only for the master server.
Regarding this problem, is it ok to assume that when this issue closes, the bug will be fixed? or do you have another tracking bug, so I can be notified when this is fixed?

Comment by Johan Wikman [ 2018-03-19 ]

Hi,
Yes, once this issue closes the bug has been fixed. And you'll also find out in what release the fix will be included.

Comment by Johan Wikman [ 2018-03-21 ]

There was a problem in the handling of multi-statements in readwritesplit.

Comment by Zeve [ 2018-04-20 ]

Hi Johan,

That specific problem might have been fixed, but I still got the same warning message: "warning: (64) [masking] Received data, although expected nothing." and the application is not working properly. I already uploaded a new zip to mariadb's FTP, please let me know if I should open a different issue.

Zeve.

Comment by Johan Wikman [ 2018-05-03 ]

Hi zeve
Sorry for not responding earlier.

Could you send me a mail with the name of the file that you uploaded.

Thanks, Johan

Comment by Johan Wikman [ 2018-05-03 ]

Thanks for the mail.

And just to be certain, could you confirm that it is with MaxScale 2.2.4 that you get these warning messages.

Comment by Zeve [ 2018-05-03 ]

Hi Johan,

Yes, I am using Maxscale 2.2.4 now. I restarted/checked the version and retested now, just to be sure.
The information I gave you is correct.

Comment by Johan Wikman [ 2018-05-03 ]

Ok thanks, I'll investigate.

Comment by Johan Wikman [ 2018-05-08 ]

Hi zeve

Does the system work? That is, is it "only" the case that you see a warning message you do not expect to see?

Johan

Comment by Zeve [ 2018-05-08 ]

Hi Johan,

The web-app works partially, it throws an error when creating a user (which has correspondence in these 'warning' messages) - though somehow the user is created - but I haven't tested it filling all the optional fields from the app when creating a user. Some other modules of the web-app work.

Zeve

Comment by Johan Wikman [ 2018-05-08 ]

After investigation, I'm quite certain it is only the logging that is wrong. That is, multi-statements are handled correctly and the warning is logged erroneously.

So, I will again close this, but have created MXS-1861 that deals with the erroneous logging.

Comment by Zeve [ 2018-05-08 ]

Hi Johan,

If only the logging is the problem, then our app should work without errors, but it throws errors when using 'R/W split' compared to 'Write-Only' service. If you need, I can provide again two sets of logs: one from a successful operation (when going though the 'Read-Only' Service) and the other one where the apps gives the error - and also the 'warning' message appears in the logs - (when going through the 'R/W split' service).

Zeve

Comment by Johan Wikman [ 2018-05-08 ]

That would be very kind of you.

And, could you please try without the masking filter, so that we would find out whether the masking filter actually plays a role here.

Johan

Comment by Zeve [ 2018-05-09 ]

Hi Johan,

I uploaded the logs and maxscale.cnf to the FTP server. The archive is called: Zeve - maxscale logs - 5.09.2018.zip .
Let me know if you need more info/logs/etc.

Zeve

UPDATE: I was using maxscale 2.2.5

Comment by Johan Wikman [ 2018-05-15 ]

Hi zeve

Thanks for the upload. Unfortunately, I only now have been able to start working on this.

Could you still try with R/W-Service but with the the masking filter excluded.

If that does not work properly, then it's likely to be an ReadWriteSplit problem but if it does, then the culprit is the masking filter or the combination of ReadWriteSplit and the masking filter.

Comment by Zeve [ 2018-05-15 ]

Hi Johan,

R/W split without the masking _ filter works fine. _Read-Only with masking works fine. Only the combination of R/W split and masking is troublesome.

Zeve.

Comment by Johan Wikman [ 2018-05-15 ]

Ok, thanks!

Comment by Johan Wikman [ 2018-05-31 ]

Hi zeve

Unfortunately I have been occupied by other issues, so I have not been able to investigate this. It would be helpful if you could check whether 2.2.6 exposes the same faulty behaviour as 2.2.4.

Johan

Comment by Zeve [ 2018-06-05 ]

Hi Johan,

I will test it again with maxscale 2.2.8, (as it is the latest version) and let you know.

Zeve

Comment by Zeve [ 2018-06-05 ]

Hi Johan,

I re-did the test and the result is the same. I uploaded the "Zeve - maxscale-2.2.8.log" file with logs on the FTP.

Zeve

Comment by Johan Wikman [ 2018-06-05 ]

Thanks!

Comment by Johan Wikman [ 2018-06-11 ]

The only thing fishy in that log are the

2018-06-05 09:11:14   info   : (130) [qc_sqlite] Parsing the query failed, cannot report query type: #log: user: root id: 1
 
2018-06-05 09:11:14   info   : (130) [qc_sqlite] Parsing the query failed, cannot report query operation: #log: user: root id: 1

lines, but as that's just a comment it should not have any impact on anything. The sqlite based parser we used simply did not recognize # as the beginning of an end-of-line comment.

If you can prevent that comment from being inserted, it would help us rule things out.

Comment by Zeve [ 2018-06-11 ]

Hi,

I'll talk to the dev guys and see if they can do something about it and let you know.

PS: it would still be a good idea to make qc_sqlite aware of these comments if possible.

Comment by Johan Wikman [ 2018-06-11 ]

Of course I'll make qc_sqlite aware of such comments; in fact that has been fixed already

Could you also ask the dev guys whether they in any situation after having sent a request, issue another one, before the response to the first one has been received?

Johan

Comment by Johan Wikman [ 2018-06-11 ]

zeve You web-app, what language is it written in and what client library do you use?

Johan

Comment by Zeve [ 2018-06-14 ]

Hi Johan,

To answer your questions:

"Your web-app, what language is it written in and what client library do you use?"

  • it's PHP! and pdo_mysql php extension is working with mysql

"Could you also ask the dev guys whether they in any situation after having sent a request, issue another one, before the response to the first one has been received?"

  • php do not have threads, everything is executed sequantially

This is what our dev guys told me.

Zeve.

Comment by Johan Wikman [ 2018-06-29 ]

Hi zeve, if you did not notice we just released 2.2.10 that correctly handles #-comments. Not that I can see how that could have any impact on the problems that you face.

Comment by markus makela [ 2020-08-27 ]

Closing as Cannot Reproduce. If this still happens with the latest releases, please let us know and we'll reopen the issue.

Generated at Thu Feb 08 04:08:54 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.