Adding a little TLS complexity to authentication_ldap_simple

In a previous post I showed that by default when authentication_ldap_simple communicates with a Windows Domain Controller (or any other LDAP service), then the password is transmitted unencrypted during authentication.

This time I’ll demonstrate how to close this loophole.  A pre-requisite is that the Domain Controller needs to be configured to accept secure connections. This is done by installing a certificate, the process is well documented elsewhere so I won’t repeat it here.

There are two different ways to configure secure communication.  The first method is to set authentication_ldap_simple_server_port to 636.

As of MySQL 8.0.14, if the LDAP port number is configured as 636 or 3269, the plugin uses LDAPS (LDAP over SSL) instead of LDAP. (LDAPS differs from startTLS.)

The second method is to set authentication_ldap_simple_tls to ON.

For simple LDAP authentication, whether connections by the plugin to the LDAP server are secure. If this variable is enabled, the plugin uses TLS to connect securely to the LDAP server.

In both cases we have to set authentication_ldap_simple_ca_path to point to the certificate authority file used when securing the domain controller.  (Pro-tip ensure the both the file attributes of this certificate and of the directory it sits in are such that the mysql process is able to access it, you won’t believe how long I wasted due to this).

Of the two methods, I have been informed that the TLS method is optimal so that is what I will demonstrate.  Note I have found that it’s better to load the plugin and set the variables in the mysql configuration file (my.cnf) and restart the service rather than setting them dynamically (it seems the otherwise the values do not correctly propagate to the appropriate processes due to LDAP connection pooling)  so that’s what I’ll show you.

[root@lnx-mysql8 ~]# tail -5 /etc/my.cnf
plugin-load-add=authentication_ldap_simple.so
authentication_ldap_simple_server_host='win-dc.windows.domain'
authentication_ldap_simple_group_search_attr=
authentication_ldap_simple_tls=ON
authentication_ldap_simple_ca_path='/etc/certs/win-dc.crt'
[root@lnx-mysql8 ~]# 

Let’s have a look at the network traffic on port 389 (LDAP) on MySQL service start.  Observe that, after some initial negotiation regards the certificate, all traffic is encrypted.

[root@lnx-mysql8 ~]# tcpflow -C port 389
tcpflow: listening on enp0s3
0w1.3.6.1.4.1.1466.20037
0(x
1.3.6.1.4.1.1466.20037
]mK?$(UI0,($
kjih98762.*&=5/+'#g@?>3210EDCB1-)%</A C 0B10UXX10UDefault City10U 0B)JJ:7 }$kwIuI_0"%21-dc.windows.domain00 F#qI925rgCbG?{ O{R?_zm+(cx7Ju&+C0A0U0U%0 d&,(V5zVmBj2ZhZw%m@VX}5A2nDf!a)n[wn:~JTm:!0`jL4yMv"8'LH+BHQ K#F _3f]t'u)5B.^/fEKIb.Tj2?03`g5.0RJaF'pH&i=QSa[m3&j~~10&=kv)S%oiH3RvK'wE-tbJ8Tl#:B9tw;MB!FT]7AA7Gn>adwCR#I:x*#IIk8.g62~hd|N_L%OIBC#V|@)o+O_Afo-At~XHt`<fV'r]"u'}GF@<h}- eBA]vEJAu|=-t7ATiPhz(stn`[9U[_s@" (O,tD/'1RT{g6}I3% 0w1.3.6.1.4.1.1466.20037 0(x 1.3.6.1.4.1.1466.20037 )=?s@9fj& *x"80,($ kjih98762.*&=5/+'#g@?>3210EDCB1-)%</A
C

To save you having to refer to previous post here is how to create the AD authenticated user using the LDAP DN (Distinguished Name):

mysql> CREATE USER 'patrick'@'%'
    ->             IDENTIFIED WITH authentication_ldap_simple
    ->             BY 'CN=patrick,CN=Users,DC=WINDOWS,DC=DOMAIN';
Query OK, 0 rows affected (0.01 sec)

I am now able to connect using my Windows username and password:

[root@lnx-mysql8 ~]# mysql                                  \
>                          --host=lnx-mysql8.windows.domain \
>                          --enable-cleartext-plugin        \
>                          --user=patrick                   \
>                          --password=Password123
mysql: [Warning] Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 16
Server version: 8.0.16-commercial MySQL Enterprise Server - Commercial

Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql>

And let’s check the network traffic to domain controller during the authentication

[root@lnx-mysql8 ~]# tcpflow -C port 389
tcpflow: listening on enp0s3
Whl+E]X=n0ucbDOBt'
.rvY* CKWLS+

No more password in plain sight. It’s still in my bash history, but that’s something I can easily resolve by not passing it as a command line argument 🙂

(MySQL) Logged and Loaded: authentication_ldap_simple_log_status or authentication_ldap_sasl_log_status not effective?

A quick one in case anyone else hits the same problem as I encountered.  The documentation for authentication_ldap_sasl_log_status and  authentication_ldap_simple_log_status states these variables can be set to a value between 1 and 5 to control the types of messages logged.

If you set them and still find nothing is logged then sett log_error_verbosity to it’s maximum value of 3 and you should find the messages are output to the error log as expected.

Thats all!

Let the wrong one in! MySQL AD Authentication with authentication_ldap_simple

I mentioned in my previous blog entry that had I encountered an issue with this plugin, and I think now that it has been fixed in the latest MySQL versions (released on 2019-04-25) it’s reasonable to share my findings.

The following tests are with MySQL Version 8.0.13. I start by installing the plugin, pointing it at my Windows Domain Controller and creating a user associated with the DN of my Windows account.

mysql> INSTALL PLUGIN authentication_ldap_simple SONAME 'authentication_ldap_simple.so';
Query OK, 0 rows affected (0.05 sec)

mysql> SET GLOBAL authentication_ldap_simple_server_host='win-dc.windows.domain';
Query OK, 0 rows affected (0.00 sec)

mysql> CREATE USER 'patrick'@'%'
    ->        IDENTIFIED WITH authentication_ldap_simple
    ->        BY 'CN=patrick,CN=Users,DC=WINDOWS,DC=DOMAIN';
Query OK, 0 rows affected (0.08 sec)

Next we test that everything works OK by trying to log in with my correct Windows password.

[patrick@WIN-CLIENT] C:\> mysql
>>                              --host=lnx-mysql8.windows.domain `
>>                              --user=patrick                   `
>>                              --password=Password123           `
>>                              --enable-cleartext-plugin
mysql: [Warning] Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 63
Server version: 8.0.13-commercial MySQL Enterprise Server - Commercial
...
mysql>

Also providing the wrong password denies access. Everything is as expected so far.

[patrick@WIN-CLIENT] C:\> mysql                                  `
>>                              --host=lnx-mysql8.windows.domain `
>>                              --user=patrick                   `
>>                              --password=WrongPassword         `
>>                              --enable-cleartext-plugin
mysql: [Warning] Using a password on the command line interface can be insecure.
ERROR 1045 (28000): Access denied for user 'patrick'@'WIN-CLIENT.windows.domain'...

However what would you expect to happen if I try to log in to this account without providing a password?  Let’s see…

[patrick@WIN-CLIENT] C:\> mysql                                  `
>>                              --host=lnx-mysql8.windows.domain `
>>                              --user=patrick                   `
>>                              --enable-cleartext-plugin
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 30
Server version: 8.0.13-commercial MySQL Enterprise Server - Commercial
...
mysql> select current_user();
+----------------+
| current_user() |
+----------------+
| patrick@%      |
+----------------+
1 row in set (0.00 sec)

Huh? It lets me in!  After double checking everything I raised an SR for this and a bug was created and fixed in 8.0.16. Apparently the 5.7 branch was also affected, and this fix is also in 5.7.26.

Bug #29637712: The authentication_ldap_simple plugin could enforce authentication incorrectly.

Let’s test in 8.0.16. Note one difference here is that I have to set variable authentication_ldap_simple_group_search_attr to ” to disable AD group checking. This behaviour, related to proxy users,  seems to have been introduced in 8.0.14, but on my lab setup this step breaks authentication completely so I disable it.

mysql> INSTALL PLUGIN authentication_ldap_simple SONAME 'authentication_ldap_simple.so';
Query OK, 0 rows affected (0.00 sec)

mysql> SET GLOBAL authentication_ldap_simple_bind_base_dn='DC=WINDOWS,DC=DOMAIN';
Query OK, 0 rows affected (0.00 sec)

mysql> SET GLOBAL authentication_ldap_simple_group_search_attr='';
Query OK, 0 rows affected (0.00 sec)

mysql> CREATE USER 'patrick'@'%'
    ->             IDENTIFIED WITH authentication_ldap_simple
    ->             BY 'CN=patrick,CN=Users,DC=WINDOWS,DC=DOMAIN';
Query OK, 0 rows affected (0.00 sec)

I won’t repeat the tests for correct and incorrect password handling, they still behave as before, but I will show you behaviour without specifying a password.

[patrick@WIN-CLIENT] C:\> mysql                                  `
>>                               --host=lnx-mysql8.windows.domain `
>>                               --user=patrick                   `
>>                               --enable-cleartext-plugin
ERROR 1045 (28000): Access denied for user 'patrick'@'WIN-CLIENT.windows.domain' (using password: YES)
[patrick@WIN-CLIENT] C:\>

I’m not sure if there is anyone using authentication_ldap_simple due to it sending passwords unencrypted between database and domain controller, but if there is, I’d suggest checking whether you are susceptible to this issue and if so applying latest patchset ASAP.

I’m also not sure if this is specific to LDAP authentication with Active Directory or other Directory Services are affected.  I also wonder whether authentication_ldap_sasl is affected, but I don’t have configuration to check that out.

mysql_clear_password & authentication_ldap_simple password encryption

Preparing for my talk at the HK Open Source Conference I wanted to confirm some of the things I had read about these plugins, mostly from Matthias Crauwels excellent article on the subject.

My lab environment consists of Windows 2016 Domain controller and client machines, with MySQL 8 running on Oracle Linux 7.

First I configure the database to use the server-side plugin, configure the plugin to point to the domain controller, and create a database user associated via the plugin with my Windows account.

mysql> INSTALL PLUGIN authentication_ldap_simple SONAME 'authentication_ldap_simple.so';
Query OK, 0 rows affected (0.05 sec)

mysql> SET GLOBAL authentication_ldap_simple_server_host='win-dc.windows.domain';
Query OK, 0 rows affected (0.00 sec)

mysql> CREATE USER 'patrick'@'%'
    ->        IDENTIFIED WITH authentication_ldap_simple
    ->        BY 'CN=patrick,CN=Users,DC=WINDOWS,DC=DOMAIN';
Query OK, 0 rows affected (0.08 sec)

Next I successfully connect from my Windows client to this database account passing in my Windows credentials.

[patrick@WIN-CLIENT] C:\> mysql --host=lnx-mysql8.windows.domain `
>>                              --user=patrick                   `
>>                              --password=Password123           `
>>                              --enable-cleartext-plugin
mysql: [Warning] Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 63
Server version: 8.0.13-commercial MySQL Enterprise Server - Commercial

Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql>

Checking the network packets between the Windows client and database server, observe that (almost all) the traffic is encrypted with a self-signed certificate.

[root@lnx-mysql8 ~]# tcpflow -c port 3306
tcpflow: listening on enp0s3
192.168.002.004.03306-192.168.002.002.49801: U
<UdYcaching_sha2_passwordLR%
192.168.002.002.49801-192.168.002.004.03306:
192.168.002.002.49801-192.168.002.004.03306: ANi<l[}y~yn+,/0#'$(g@kj
239-.<>%=h&/05612?)i*17
U


0H1212013500Z0@1>0<U5MySQL_Server_8.0.13_Auto_Generated_Server_Certificate0"0
DH<@_Cn%VR9A)[QLMVjAYe1Kju2\)Wk7SqOG02Xl;>n)i&gjV:/,J^f("qBDH8kW:lKQ+B 3;K^!.$5BxJ=0XWD,00U00
^uBey@/e;m4sQ
lJDiU{?s;[72FeLkS
p{WFXdr**yLPp'ij_(z`E"{Lxu|1DX$Jp`w;Ti<}BlLA@?
0H1212013500Z0<1:08U1MySQL_Server_8.0.13_Auto_Generated_CA_Certificate0"0 2 |s?jupq&GG]5`-2$1'$,AT"`OA/^d((~:n0Z'~O?$+az]y(De"5Klwiv(B"ST~rE0'7qIWZc%R$D8v9MzF|\blAK00U00 9()~I?-Nq(#LRACVU>eOWB["IOm$\]fvNa7W\m?
dYt^dT)-Y&UWUBlnmOA}?%YW>D
C*<*f,OD^^G"
'#-F*/=@=]mnDRVQ,RG(a|la^!fH)5"{EbynK4{q:CiV%#(f_hr_/-X~S/:
(@C{jB&{%ddU-F0fG/2t_aPUw\A%&+:{K"t(+}Q~+|#XxJNS\XhDz);=79.o{Q<sp??D^0\v:6[a|$ooBZ(K0Zt}. WjeoWOi4AE]YkQXUH0E2;'US-/Dw0[4@&3]]/c`GCEEzmU@oG2{%Z&`0!A}]A[.:m 7q@w]Rv3-nKZP$N''}yjKssvFvc:O$'rU)f(=@,Wup,>b+xF[Lv6;
192.168.002.004.03306-192.168.002.002.49801: ,
{xsGdN>
XEUyH`?T'd7fI JwN%:eq2#;y'Nh(hm}c$dG'zs
zT@(W$]#Wm4nw2t7(`X-5lK'SXwk0qS3
192.168.002.002.49801-192.168.002.004.03306: =@,Wa{q%)}aH9;.%~k$hoKI+a8\B}@NR@Dp`JFDwK\(1%9 %5XqO f:Pgmvi|>N^&=k/~egl]i@s;p
\8&?4AKg>r63E
192.168.002.004.03306-192.168.002.002.49801: H`XmX2:@~Oq)BY-|<`GS6ew 192.168.002.002.49801-192.168.002.004.03306: 0=@,W.la:QC0,%>G~L6
192.168.002.004.03306-192.168.002.002.49801: #`X-$~v4_L3
|s
192.168.002.002.49801-192.168.002.004.03306: ==@,W.BFu?6'F6|P)EC]?%n)ww
nSHK*+@6FS(9l|Y2>apy;-192.168.002.002.49801: |`X,

Note however it is possible to disable this encryption with the –ssl-mode=disabled flag.

[patrick@WIN-CLIENT] C:\> mysql --host=lnx-mysql8.windows.domain `
>>                              --user=patrick                   `
>>                              --password=Password123           `
>>                              --enable-cleartext-plugin        `
>>                              --ssl-mode=disabled
mysql: [Warning] Using a password on the command line interface can be insecure.
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 64
Server version: 8.0.13-commercial MySQL Enterprise Server - Commercial

Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql>

Observe that the password is now transmitted unencrypted during authentication

[root@lnx-mysql8 ~]# tcpflow -c port 3306
tcpflow: listening on enp0s3
192.168.002.004.03306-192.168.002.002.49899: U
8.0.13-commercialAi95M2)P3(f}3caching_sha2_password
192.168.002.002.49899-192.168.002.004.03306: patrick lv
J5T{W0J-rcaching_sha2_passwordq_pid172program_namemysql_client_namelibmysql_thread2640_client_version8.0.13_osWin64_platformx86_64
192.168.002.004.03306-192.168.002.002.49899: mysql_clear_password
192.168.002.002.49899-192.168.002.004.03306: Password123
192.168.002.004.03306-192.168.002.002.49899:
192.168.002.002.49899-192.168.002.004.03306: !select @@version_comment limit 1
192.168.002.004.03306-192.168.002.002.49899: 'def@@version_comment$%$MySQL Enterprise Server - Commercial

Such connections can be prevented with the require_secure_transport=ON variable

mysql> SET GLOBAL require_secure_transport=ON;
Query OK, 0 rows affected (0.00 sec)

In this case connections which disable encryption will be rejected

[patrick@WIN-CLIENT] C:\> mysql --host=lnx-mysql8.windows.domain `
>>                              --user=patrick                   `
>>                              --password=Password123           `
>>                              --enable-cleartext-plugin        `
>>                              --ssl-mode=disabled
mysql: [Warning] Using a password on the command line interface can be insecure.
ERROR 3159 (HY000): Connections using insecure transport are prohibited while --require_secure_transport=ON.
[patrick@WIN-CLIENT] C:\>

Unfortunately even though the connection is rejected, the password is still transmitted unencrypted during authentication process

[root@lnx-mysql8 ~]# tcpflow -c port 3306
tcpflow: listening on enp0s3
192.168.002.004.03306-192.168.002.002.49867: U
8.0.13-commercial@=l?K/sbq!Qa&sG{{Bcaching_sha2_password
192.168.002.002.49867-192.168.002.004.03306: patrick Au'"?..`%85n]~caching_sha2_passwordr_pid3416program_namemysql_client_namelibmysql_thread4992_client_version8.0.13_osWin64_platformx86_64
192.168.002.004.03306-192.168.002.002.49867: mysql_clear_password
192.168.002.002.49867-192.168.002.004.03306: Password123
192.168.002.004.03306-192.168.002.002.49867: aW#HY000Connections using insecure transport are prohibited while --require_secure_transport=ON.

However if we re-run the original connection attempt (with encrypted traffic between database client and server)  capturing the network traffic between database and domain controller, we can see password is transferred unencyrpted as this point

[root@lnx-mysql8 .passwords]# tcpflow -c port 389
tcpflow: listening on enp0s3
192.168.002.004.43068-192.168.002.001.00389: 0PcK

NtVer0mainWINDOWS.DOMAIN
netlogon
192.168.002.001.00389-192.168.002.004.43070: 0d00znetlogon1jhl)X0K4fWINDOWSDOMAINWIN-DCWINDOWSWIN-DCDefault-First-Site-NameE0e

192.168.002.004.43070-192.168.002.001.00389: 0B
192.168.002.004.42990-192.168.002.001.00389: 0?`:(CN=patrick,CN=Users,DC=WINDOWS,DC=DOMAINPassword123
192.168.002.001.00389-192.168.002.004.42990: 0a

The documentation alludes to some of the restrictions, although to my mind it seems to focus on the encryption between database client and server, but not between database server and Domain Controller (unless I’ve missed something).

The server-side authentication_ldap_simple plugin performs simple LDAP authentication. For connections by accounts that use this plugin, client programs use the client-side mysql_clear_password plugin, which sends the password to the server in clear text. No password hashing or encryption is used, so a secure connection between the MySQL client and server is recommended to prevent password exposure.

Based on the above observations, as I was expecting, this plugin combination is not really suitable for implementation for any environment which takes security seriously.

If that wasn’t enough reason to avoid the plugin, during the course of my investigation I discovered some other surprising behavior.  Based on discussion with Oracle support this should be resolved in the next release of SQL Server, so I’ll wait till that is released before sharing.

 

Problems with Binding Arrays

Recently some of our developers have moved forwards with fixing some code that has been using literals, instead of bind variables.  A complication is that they are using lists of values, so the SQL they were generating was of format

WHERE COL1 IN (1,2,3,4)

They resolved this by using an array in Java and construct similar to the following:

WHERE COL1 IN (SELECT * FROM TABLE(?))

However when moving to the new method performance degraded, they were getting full table scans where previously they were getting index access.
Initially I thought we could resolve this by using a cardinality hint on the TABLE select ie:

WHERE COL1 IN (SELECT /*+CARDINALITY(t 1) */ * FROM TABLE(?) t)

However this didn’t help much. I’ve managed to reproduce the problem to the testcase below (running on 18c):

SQL> CREATE TABLE t1
  2      AS
  3          SELECT
  4              ROWNUM id,
  5              rpad('x', 100) padding
  6          FROM
  7              dual
  8          CONNECT BY
  9              level  <= 4000; -- comment to avoid WordPress format issue  

Table T1 created.

SQL> create index t1_i1 on t1(id);

Index T1_I1 created.

SQL> exec dbms_stats.gather_table_stats(null, 't1');

PL/SQL procedure successfully completed.

SQL> create or replace type n_t as table of number;
  2  /

Type N_T compiled

SQL> SELECT /*+ gather_plan_statistics */  NULL
  2      FROM
  3        (SELECT DISTINCT a.id
  4              FROM t1   a)
  5      WHERE
  6          id IN (1)
  7  /
NULL



SQL> select * from table(dbms_xplan.display_cursor(format=>'allstats last'));
PLAN_TABLE_OUTPUT
SQL_ID  a18bwsyqx37gs, child number 0
-------------------------------------
SELECT /*+ gather_plan_statistics */  NULL     FROM       (SELECT
DISTINCT a.id             FROM t1   a)     WHERE         id IN (1)

Plan hash value: 405044659

---------------------------------------------------------------------------------------
| Id  | Operation           | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
---------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |       |      1 |        |      1 |00:00:00.01 |       2 |
|   1 |  VIEW               |       |      1 |      1 |      1 |00:00:00.01 |       2 |
|   2 |   SORT UNIQUE NOSORT|       |      1 |      1 |      1 |00:00:00.01 |       2 |
|*  3 |    INDEX RANGE SCAN | T1_I1 |      1 |      1 |      1 |00:00:00.01 |       2 |
---------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - access("A"."ID"=1)



21 rows selected.

SQL> SELECT /*+ gather_plan_statistics */  NULL
  2      FROM
  3        (SELECT DISTINCT a.id
  4              FROM t1   a)
  5      WHERE
  6          id IN (SELECT /*+cardinality(nt 1) */ column_value FROM TABLE ( n_t(1) ) nt)
  7  /
NULL



SQL> select * from table(dbms_xplan.display_cursor(format=>'allstats last'));
PLAN_TABLE_OUTPUT
SQL_ID  cwcsdhm543ph2, child number 0
-------------------------------------
SELECT /*+ gather_plan_statistics */  NULL     FROM       (SELECT
DISTINCT a.id             FROM t1   a)     WHERE         id IN (SELECT
/*+cardinality(nt 1) */ column_value FROM TABLE ( n_t(1) ) nt)

Plan hash value: 1445712880

----------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                               | Name    | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                        |         |      1 |        |      1 |00:00:00.01 |      64 |       |       |          |
|*  1 |  HASH JOIN RIGHT SEMI                   |         |      1 |      1 |      1 |00:00:00.01 |      64 |  2546K|  2546K|  303K (0)|
|   2 |   JOIN FILTER CREATE                    | :BF0000 |      1 |      1 |      1 |00:00:00.01 |       0 |       |       |          |
|   3 |    COLLECTION ITERATOR CONSTRUCTOR FETCH|         |      1 |      1 |      1 |00:00:00.01 |       0 |       |       |          |
|   4 |   VIEW                                  |         |      1 |   4000 |      1 |00:00:00.01 |      64 |       |       |          |
|   5 |    HASH UNIQUE                          |         |      1 |   4000 |      1 |00:00:00.01 |      64 |  2294K|  2294K|  514K (0)|
|   6 |     JOIN FILTER USE                     | :BF0000 |      1 |   4000 |      1 |00:00:00.01 |      64 |       |       |          |
|*  7 |      TABLE ACCESS FULL                  | T1      |      1 |   4000 |      1 |00:00:00.01 |      64 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("ID"=VALUE(KOKBF$))

PLAN_TABLE_OUTPUT
   7 - filter(SYS_OP_BLOOM_FILTER(:BF0000,"A"."ID"))



27 rows selected.

SQL>

Fundmentally I think the problem is the optimzer is unable to push the TABLE function into the inner select.
For the moment we’re having to revert to a hybrid solution where they generate SQL such as the following:

WHERE COL1 IN (?,?,?,?)

Each value has to be bound seperately. It’s not ideal as shared pool is somewhat full of each variation depending on how many values there are.  Also they are having to do a soft parse of the cursor each time, rather than parsing once and re-using.

However other than getting the developers to rewrite all their queries I don’t see any better solution at the moment.

Resource manager session_pga_limit has it’s own limits

Recently we hit an issue with a complex SQL statement (formatted was 44,000 lines, maybe subject of a separate blog post), causing the CBO to struggle consuming large amounts of PGA memory, and the host to start swapping memory and impacting other database users.

The pga_aggregate_limit parameter did not appear to be kicking in (maybe because this was happening during parse phase), so while looking for a proper solution we considered other ways to limit the effect of this problem SQL.

As we are on release 12.2 one thing we tried was a (relatively new) feature of resource manager, session_pga_limit. This should limit the PGA any one session can consume (as opposed to pga_aggregate_limit which is instance wide), however new features can be a little temperamental, especially in the first few versions after they have been introduced.

After a bit of trial and error we determined that setting it to any value greater than 4G (4096 MB) causes the feature not to kick in.

The following is my testcase on a 12.2.0.1.180717 PDB. I could not reproduce this behavior on 18c (non-multitenant) implying this limitation (bug?) has likely been fixed.

First we create a resource manager plan, consumer groups and directives, and configure the instance to use this plan.

SQL> BEGIN
  2    sys.DBMS_RESOURCE_MANAGER.clear_pending_area();
  3
  4    sys.DBMS_RESOURCE_MANAGER.create_pending_area();
  5
  6    sys.DBMS_RESOURCE_MANAGER.create_plan(
  7      plan    => 'PGA_PLAN',
  8      comment => 'Plan to demonstrate behaviour with session_pga_limit >= 4096');
  9
 10    sys.DBMS_RESOURCE_MANAGER.create_consumer_group(
 11      consumer_group => 'PGA_LIMIT_4095_GROUP',
 12      comment        => '4095 MB PGA Limit');
 13
 14    sys.DBMS_RESOURCE_MANAGER.create_consumer_group(
 15      consumer_group => 'PGA_LIMIT_4096_GROUP',
 16      comment        => '4096 MB PGA Limit');
 17
 18    sys.DBMS_RESOURCE_MANAGER.create_plan_directive (
 19      plan              => 'PGA_PLAN',
 20      group_or_subplan  => 'PGA_LIMIT_4095_GROUP',
 21      session_pga_limit => 4095);
 22
 23    sys.DBMS_RESOURCE_MANAGER.create_plan_directive (
 24      plan              => 'PGA_PLAN',
 25      group_or_subplan  => 'PGA_LIMIT_4096_GROUP',
 26      session_pga_limit => 4096);
 27
 28    sys.DBMS_RESOURCE_MANAGER.create_plan_directive (
 29      plan              => 'PGA_PLAN',
 30      group_or_subplan  => 'OTHER_GROUPS');
 31
 32    sys.DBMS_RESOURCE_MANAGER.validate_pending_area;
 33
 34    sys.DBMS_RESOURCE_MANAGER.submit_pending_area();
 35  END;
 36  /

PL/SQL procedure successfully completed.

SQL> ALTER SYSTEM SET RESOURCE_MANAGER_PLAN = PGA_PLAN;

System altered.

Then we configure my test user to use the consumer group limiting it to 4095 MB PGA.

SQL> BEGIN
  2    sys.DBMS_RESOURCE_MANAGER.clear_pending_area();
  3    sys.DBMS_RESOURCE_MANAGER.create_pending_area();
  4
  5    sys.DBMS_RESOURCE_MANAGER.set_consumer_group_mapping (
  6      attribute      => DBMS_RESOURCE_MANAGER.oracle_user,
  7      value          => 'TEST_PGA_USER',
  8      consumer_group => 'PGA_LIMIT_4095_GROUP');
  9
 10    sys.DBMS_RESOURCE_MANAGER.validate_pending_area;
 11    sys.DBMS_RESOURCE_MANAGER.submit_pending_area();
 12  END;
 13  /

We connect as the test user, and executing some stupid PL/SQL that sits in a tight loop eating PGA. Observe that the resource manager directive is obeyed when the PGA hits 4095 MB.

SQL>   declare
  2          type vc_tt is table of VARCHAR2(32767);
  3          vc_t vc_tt := vc_tt() ;
  4      begin
  5          while TRUE
  6          loop
  7               vc_t.extend();
  8          end loop;
  9      end;
 10   /
  declare
*
ERROR at line 1:
ORA-04068: existing state of packages has been discarded
ORA-10260: PGA limit (4095 MB) exceeded - process terminated
ORA-06512: at line 7

Let’s remap my test user to the consumer group limited to 4096 MB.

SQL> BEGIN
  2    sys.DBMS_RESOURCE_MANAGER.clear_pending_area();
  3    sys.DBMS_RESOURCE_MANAGER.create_pending_area();
  4
  5    sys.DBMS_RESOURCE_MANAGER.set_consumer_group_mapping (
  6      attribute      => DBMS_RESOURCE_MANAGER.oracle_user,
  7      value          => 'TEST_PGA_USER',
  8      consumer_group => 'PGA_LIMIT_4096_GROUP');
  9
 10    sys.DBMS_RESOURCE_MANAGER.validate_pending_area;
 11    sys.DBMS_RESOURCE_MANAGER.submit_pending_area();
 12  END;
 13  /

PL/SQL procedure successfully completed.

My test program runs unchecked:

SQL> declare
  2      type vc_tt is table of VARCHAR2(32767);
  3      vc_t vc_tt := vc_tt() ;
  4  begin
  5      while TRUE
  6      loop
  7           vc_t.extend();
  8      end loop;
  9  end;
 10  /

Checking PGA allocation from another session we can see it’s up to 8546MB, way past the 4096MB it should be limited to.

SQL>  SELECT
  2      spid,
  3      resource_consumer_group,
  4      round(pga_used_mem / 1024 / 1024) pga_used_mb
  5  FROM
  6      v$session s,
  7      v$process p
  8  WHERE
  9      s.username LIKE 'TEST_PGA_USER'
 10      AND p.addr = s.paddr;

SPID                     RESOURCE_CONSUMER_GROUP          PGA_USED_MB
------------------------ -------------------------------- -----------
234513                   PGA_LIMIT_4096_GROUP                    8546

Note if you’re testing this yourself, I suggest to be careful, don’t do this on a production instance and be prepared to kill the run-away session forcefully.

Fun with SQL Translation Framework – By-Passing Parse Errors

Invalid SQL being sent to the database is something to watch out for,
it’s a real performance killer because once SQL is rejected by parser,
it is not cached in shared pool, resulting in hard parse every time the SQL is encountered.

One cool new feature of Oracle 12.2 is the fact that such SQL parse errors are automatically logged to the alert log (by default every 100 occurrences of a particular SQL)

(Random thoughts, the database must be storing these invalid SQL somewhere to keep track of the parse error count, I wonder where that is? I guess though that even though it has stored cached the statement in it’s “Invalid SQL” list it will still have to re-parse every time it’s encountered as the statement may become valid if say a table it relied on got created).  (Edit: 2018-10-10 As is often the case, Jonathan Lewis seems to have the answer to this)

A similar effect can be achieved on previous versions by setting event 10035.

One instance that I’ve been monitoring has regular occurrences of the following SQL:

SELECT INVALID SELECT STATEMENT TO FORCE ODBC DRIVER TO UNPREPARED STATE

A quick google returns lots of hits, but no real solution. Oracle Support bug 8469553 also has some clues. Basically it seems to be a problem with older versions of ODBC, and likely solution is to upgrade ODBC version.

However I was thinking about a short-term fix, and recalled a presentation from Kerry Osborne regarding SQL Translation Framework to transform one SQL statement to another, and wondered whether I could transform this invalid statement to a valid one?

To my surprise it worked, as I demonstrate below:

SQL> begin
  2     dbms_sql_translator.create_profile('odbc_profile');
  3     dbms_sql_translator.register_sql_translation( profile_name => 'odbc_profile',
  4                                                   sql_text => 'SELECT INVALID SELECT STATEMENT TO FORCE ODBC DRIVER TO UNPREPARED STATE',
  5                                                   translated_text => 'SELECT DUMMY FROM DUAL');
  6  end;
  7  /

PL/SQL procedure successfully completed.

SQL> alter session set sql_translation_profile=odbc_profile;

Session altered.

SQL> alter session set events = '10601 trace name context forever, level 32';

Session altered.

SQL> SELECT INVALID SELECT STATEMENT TO FORCE ODBC DRIVER TO UNPREPARED STATE;
D
-
X

SQL>

Now I’m not sure if this has any knock on effects on the application in question, but at least goes to show a usage of the SQL Translation Framework that I hadn’t seen or considered before.

I’m sure there are many more.

 

Autonomous MView Log Shrinkage

With version 12.2 there seems to have a some change in behavior of Materialised View Logs which caught us by surprise; I haven’t seen it documented elsewhere, so let me demonstrate.

My test instance is un-patched 12.2.0.1 running on Oracle Linux.

For the setup, I create a table, a mview log on that table, a mview that can use the mview log and a stored procedure that can insert and delete rows from the table (thus populating the mview log).

SQL> CREATE TABLE detail (
  2      id        NUMBER
  3          GENERATED BY DEFAULT ON NULL AS IDENTITY
  4      PRIMARY KEY,
  5      padding   VARCHAR2(255)
  6  );

Table DETAIL created.

SQL> CREATE MATERIALIZED VIEW LOG ON detail WITH
  2      ROWID,
  3      SEQUENCE ( id,
  4                 padding )
  5      INCLUDING NEW VALUES;

Materialized view log DETAIL created.

SQL> CREATE MATERIALIZED VIEW summary AS
  2      SELECT
  3          COUNT(*)
  4      FROM
  5          detail;

Materialized view SUMMARY created.

SQL> CREATE PROCEDURE insert_and_delete AS
  2  BEGIN
  3      INSERT /*+append*/ INTO detail ( padding )
  4          SELECT
  5              lpad('X',255,'X')
  6          FROM
  7              dual
  8          CONNECT BY
  9              level  comment to avoid WordPress format issue
 10              ;  
 11  
 12      COMMIT; 
 13      DELETE FROM detail;  
 14  
 15      COMMIT;
 16  END;
 17  /
 Procedure INSERT_AND_DELETE compiled 
SQL>

Then I call the stored procedure to populate the mview log, and then perform a fast refresh.

SQL> EXEC insert_and_delete;

PL/SQL procedure successfully completed.

SQL> EXEC dbms_mview.refresh('summary','f');

PL/SQL procedure successfully completed.

SQL>

Observe from the alert log that because the entries in the mview log have been deleted as part of the fast refresh, Oracle determines that it is appropriate to enable row movement on the mview log table and perform a “shrink space” operation.

MVRF: kkzlShrinkMVLog: recommendations: Enable row movement of the table PATRICK.MLOG$_DETAIL and perform shrink, estimated savings is 38789120 bytes.
MVRF: kkzlShrinkMVLog: executed: alter table "PATRICK"."MLOG$_DETAIL" enable row movement
MVRF: kkzlShrinkMVLog: executed: alter table "PATRICK"."MLOG$_DETAIL" shrink space

Re-running the test, it is not necessary to re-enable row movement (the table retains this setting), so the “shrink space” action only is executed.

SQL> EXEC insert_and_delete;

PL/SQL procedure successfully completed.

SQL> EXEC dbms_mview.refresh('summary','f');

PL/SQL procedure successfully completed.

SQL>
MVRF: kkzlShrinkMVLog: recommendations: Perform shrink, estimated savings is 38789120 bytes.
MVRF: kkzlShrinkMVLog: executed: alter table "PATRICK"."MLOG$_DETAIL" shrink space

This behavior caused us some problems on our live system, because other sessions were blocked trying to refresh the mview while the shrink space was running.

Oracle Support Doc ID 2320441.1 describes this behavior, and suggests that an underscore parameter, _mv_refresh_shrink_log can be used to disable the shrink space.

I re-run my test-case with this set at session level

SQL> ALTER SESSION SET "_mv_refresh_shrink_log" = false;

Session altered.

SQL> EXEC insert_and_delete;

PL/SQL procedure successfully completed.

SQL> EXEC dbms_mview.refresh('summary','f');

PL/SQL procedure successfully completed.

SQL>

Monitoring the alert log, it can be seen that the “shrink space” operation no longer takes place.

If you apply this change you may want to keep an eye on your mview log sizes, and shrink manually if necessary.

Do you come here often? 12.2 change in behavior for DBA_USERS.LAST_LOGIN with Proxy Authentication

The behavior of the LAST_LOGIN field on DBA_USERS has changed with respect to proxy authentication (for the better I think).

Proxy authentication is an feature of the Oracle Database that effective allows you to be connected as one user (the client user to use Oracle’s terminology), but using the credentials of another user (the proxy user). This is useful in combination with using personal accounts (one for every user) as the proxy users, using application accounts as the client users, avoiding the need for users to share application account passwords.

The test-case below demonstrates that when using proxy authentication in 12.1, the last login for the client user (only) is updated.

[oracle@lnx-ora121 ~]$ sqlplus / as sysdba

SQL*Plus: Release 12.1.0.2.0 Production on Mon Sep 17 05:03:55 2018

Copyright (c) 1982, 2014, Oracle. All rights reserved.
Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

SQL> create user proxy_user identified by proxy_user;

User created.

SQL> create user client_user identified by client_user;

User created.

SQL> grant create session to proxy_user;

Grant succeeded.

SQL> grant create session to client_user;

Grant succeeded.

SQL> alter user client_user grant connect through proxy_user;

User altered.

SQL> exit
Disconnected from Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options
[oracle@lnx-ora121 ~]$ sqlplus proxy_user[client_user]/proxy_user

SQL*Plus: Release 12.1.0.2.0 Production on Mon Sep 17 05:05:13 2018

Copyright (c) 1982, 2014, Oracle. All rights reserved.
Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

SQL> exit
Disconnected from Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options
[oracle@lnx-ora121 ~]$ sqlplus / as sysdba

SQL*Plus: Release 12.1.0.2.0 Production on Mon Sep 17 05:05:45 2018

Copyright (c) 1982, 2014, Oracle. All rights reserved.
Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options

SQL> select last_login from dba_users where username = 'PROXY_USER';

LAST_LOGIN
---------------------------------------------------------------------------
SQL> select last_login from dba_users where username = 'CLIENT_USER';

LAST_LOGIN
---------------------------------------------------------------------------
17-SEP-18 05.05.33.000000000 AM +00:00

SQL>

Contrast this behavior with that of the same test running on 12.2 and you can see that now it is the proxy user that has their last login time updated.

[oracle@lnx-ora122 ~]$ sqlplus / as sysdba 

SQL*Plus: Release 12.2.0.1.0 Production on Mon Sep 17 05:04:22 2018

Copyright (c) 1982, 2016, Oracle.  All rights reserved.


Connected to:
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production

SQL> create user proxy_user identified by proxy_user;

User created.

SQL> create user client_user identified by client_user;

User created.

SQL> grant create session to proxy_user;

Grant succeeded.

SQL> grant create session to client_user;

Grant succeeded.

SQL> alter user client_user grant connect through proxy_user;

User altered.

SQL> exit
Disconnected from Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production
[oracle@lnx-ora122 ~]$ sqlplus proxy_user[client_user]/proxy_user

SQL*Plus: Release 12.2.0.1.0 Production on Mon Sep 17 05:06:25 2018

Copyright (c) 1982, 2016, Oracle.  All rights reserved.


Connected to:
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production

SQL> exit
Disconnected from Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production

[oracle@lnx-ora122 ~]$ sqlplus proxy_user[client_user]/proxy_user                     

SQL*Plus: Release 12.2.0.1.0 Production on Mon Sep 17 05:07:18 2018

Copyright (c) 1982, 2016, Oracle.  All rights reserved.

^CERROR:
ORA-28547: connection to server failed, probable Oracle Net admin error


[oracle@lnx-ora122 ~]$ sqlplus / as sysdba                                            

SQL*Plus: Release 12.2.0.1.0 Production on Mon Sep 17 05:07:42 2018

Copyright (c) 1982, 2016, Oracle.  All rights reserved.


Connected to:
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production

SQL> select last_login from dba_users where username = 'PROXY_USER';

LAST_LOGIN
---------------------------------------------------------------------------
17-SEP-18 05.07.05.000000000 AM +00:00

SQL> select last_login from dba_users where username = 'CLIENT_USER';

LAST_LOGIN
---------------------------------------------------------------------------


SQL

 
Previously if an account was only being used as a proxy user, there was no way of knowing it was actually being used (without implementing a login trigger and storing the login time in a separate table). With this change we can know for such a user account if and when it is being used.

AWR Reports: Don’t Trust the Numbers

After implementing a recent change, and I pulled of a quick AWR report to compare performance.  At first glance I was impressed by significant improvement in “log file parallel write” event, which had halved from 2 millisecond to 1 millisecond, but something about the numbers didn’t quite look right.

Before:
before

After:
after

Let’s calculate the average wait times ourselves:
Before:  2,346s/1,482,747=0.00158219844s=1.58 ms.
After:  2,658s/1,785,172=0.00148893215s=1.49 ms.

So AWR rounds to the nearest millisecond, and this has turned an actual 6% (=(1.58-1.49)/1.58*100)  improvement into a 100% improvement.

Note that in Oracle 12.2 AWR handles this much better by reporting wait events in microseconds, one more reason to upgrade!