0

ERROR: XX000: cache lookup failed for function 1 avec CREATE EXTENSION

twitterlinkedinmail

Avec le concours de Rémi Vidier.

Disclaimer : Attention cet article utilise des outils de débogage qui sont intrusifs, et qui stoppent notamment l’exécution du processus qui est tracé, donc A NE PAS UTILISER EN PRODUCTION !!!


Cette semaine nous devions déployer notre solution d’administration à distance AllDB sur une instance PostgreSQL 11.5 chez un de nos clients. La partie qui gère ce que l’on appelle en interne le ‘palmarès‘ des requêtes lentes se base sur l’extension pg_stat_statements, ce qui implique l’installation des contribs en prérequis.

Lorsque nous avons voulu créer l’extension après avoir ajouté les différents paramètres dans postgresql.conf:

(...)
shared_preload_libraries = '/usr/pgsql-11/lib/pg_stat_statements.so'    # (change requires restart)
pg_stat_statements.max = 4000
pg_stat_statements.track = all
pg_stat_statements.track_utility = on
pg_stat_statements.save = on
track_activity_query_size = 4096
(...)

…le CREATE EXTENSION est sorti en erreur:

postgres=# create extension pg_stat_statements ;
ERROR:  XX000: cache lookup failed for function 1
LOCATION:  fmgr_info_cxt_security, fmgr.c:181

On s’est rapidement rendu compte qu’en fait le problème n’était pas lié à l’extension en elle-même, car toutes les extensions des contribs étaient concernées:

postgres=# create extension hstore ;
ERROR:  XX000: cache lookup failed for function 1
LOCATION:  fmgr_info_cxt_security, fmgr.c:181
Time: 10.104 ms

OK, donc cette fonction fmgr_info_cxt_security() doit vérifier que l’oid d’une fonction non built-in qui lui est passée en argument se trouve bien dans pg_proc, sinon cette erreur est renvoyée:

fmgr_info_cxt_security(Oid functionId, FmgrInfo *finfo, MemoryContext mcxt,
                        bool ignore_security)
 { (...)
    if ((fbp = fmgr_isbuiltin(functionId)) != NULL)
     {
         /*
          * Fast path for builtin functions: don't bother consulting pg_proc
          */
         finfo->fn_nargs = fbp->nargs;
         finfo->fn_strict = fbp->strict;
         finfo->fn_retset = fbp->retset;
         finfo->fn_stats = TRACK_FUNC_ALL;   /* ie, never track */
         finfo->fn_addr = fbp->func;
         finfo->fn_oid = functionId;
         return;
     }
 
     /* Otherwise we need the pg_proc entry */
     procedureTuple = SearchSysCache1(PROCOID, ObjectIdGetDatum(functionId));
     if (!HeapTupleIsValid(procedureTuple))
         elog(ERROR, "cache lookup failed for function %u", functionId);
     procedureStruct = (Form_pg_proc) GETSTRUCT(procedureTuple);
(...)

Dans notre cas l’oid passé en argument est 1, ce qui effectivement n’existe pas dans pg_proc, d’où l’erreur.

Si on s’intéresse à la séquence lors de laquelle cet oid=1 est remonté, il nous faut attacher gdb à l’exécution du backend qui génère l’erreur. Il porte le PID 9599, on s’attache et on pose un bp sur errfinish pour stopper l’exécution sur notre erreur:

root@centos7 ~]# ps -fu postgres 
UID        PID  PPID  C STIME TTY          TIME CMD
postgres  2821  2820  0 oct.07 pts/1   00:00:00 -bash
postgres  3234     1  0 oct.07 ?       00:00:01 /usr/pgsql-11/bin/postmaster -D /var/lib/pgsql/11/data/
postgres  3236  3234  0 oct.07 ?       00:00:00 postgres: logger   
postgres  3512  3234  0 oct.07 ?       00:00:00 postgres: checkpointer   
postgres  3513  3234  0 oct.07 ?       00:00:01 postgres: background writer   
postgres  3514  3234  0 oct.07 ?       00:00:01 postgres: walwriter   
postgres  3515  3234  0 oct.07 ?       00:00:01 postgres: autovacuum launcher   
postgres  3516  3234  0 oct.07 ?       00:00:02 postgres: stats collector   
postgres  3517  3234  0 oct.07 ?       00:00:00 postgres: logical replication launcher   
postgres  9598  2821  0 14:44 pts/1    00:00:00 psql
postgres  9599  3234  0 14:44 ?        00:00:00 postgres: postgres postgres [local] idle

root@centos7 ~]# gdb -p 9599
GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-115.el7
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Attaching to process 9599
Reading symbols from /usr/pgsql-11/bin/postgres...Reading symbols from /usr/lib/debug/usr/pgsql-11/bin/postgres.debug...done.
done.
(gdb) set pagination off
(gdb) set logging file debug.log
(gdb) set logging on
Copying output to debug.log.
(gdb) break errfinish
Breakpoint 1 at 0x84e250: file elog.c, line 414.
(gdb) cont
Continuing.

Une fois le bp posé, dans le backend on force l’erreur à nouveau, et avec les symboles de PG11 installés (postgresql11-debuginfo.x86_64) on récupère la backtrace suivante :


Breakpoint 1, errfinish (dummy=dummy@entry=0) at elog.c:414
414     elog.c: Aucun fichier ou dossier de ce type.
(gdb) ^CQuit
(gdb) bt
#0  errfinish (dummy=dummy@entry=0) at elog.c:414
#1  0x0000000000851fa8 in elog_finish (elevel=elevel@entry=20, fmt=fmt@entry=0x898698 "cache lookup failed for function %u") at elog.c:1376
#2  0x0000000000853fce in fmgr_info_cxt_security (functionId=1, functionId@entry=42165528, finfo=finfo@entry=0x7fff47c08f80, mcxt=<optimized out>, ignore_security=ignore_security@entry=false) at fmgr.c:181
#3  0x0000000000855532 in fmgr_info (finfo=0x7fff47c08f80, functionId=42165528) at fmgr.c:126
#4  OidFunctionCall1Coll (functionId=functionId@entry=1, collation=collation@entry=0, arg1=arg1@entry=24583) at fmgr.c:1411
#5  0x000000000053ba61 in ProcedureCreate (procedureName=<optimized out>, procNamespace=procNamespace@entry=2200, replace=<optimized out>, returnsSet=returnsSet@entry=false, returnType=returnType@entry=2278, proowner=10, languageObjectId=languageObjectId@entry=13, languageValidator=languageValidator@entry=1, prosrc=prosrc@entry=0x282b830 "pg_stat_statements_reset", probin=probin@entry=0x282b938 "$libdir/pg_stat_statements", prokind=prokind@entry=102 'f', security_definer=security_definer@entry=false, isLeakProof=isLeakProof@entry=false, isStrict=isStrict@entry=false, volatility=volatility@entry=118 'v', parallel=parallel@entry=115 's', parameterTypes=parameterTypes@entry=0x2836500, allParameterTypes=allParameterTypes@entry=0, parameterModes=parameterModes@entry=0, parameterNames=parameterNames@entry=0, parameterDefaults=parameterDefaults@entry=0x0, trftypes=trftypes@entry=0, proconfig=proconfig@entry=0, procost=procost@entry=1, prorows=prorows@entry=0) at pg_proc.c:703
#6  0x00000000005b0460 in CreateFunction (pstate=pstate@entry=0x2836350, stmt=stmt@entry=0x282d080) at functioncmds.c:1094
#7  0x000000000074a267 in ProcessUtilitySlow (pstate=pstate@entry=0x2836350, pstmt=pstmt@entry=0x282b2c8, queryString=queryString@entry=0x2831398 "/* contrib/pg_stat_statements/pg_stat_statements--1.4.sql */\n\n-- complain if script is sourced in psql, rather than via CREATE EXTENSION\n\n\n-- Register functions.\nCREATE FUNCTION pg_stat_statements_res"..., context=context@entry=PROCESS_UTILITY_QUERY, params=params@entry=0x0, queryEnv=queryEnv@entry=0x0, completionTag=completionTag@entry=0x0, dest=0xcf13a0 <donothingDR>) at utility.c:1473
#8  0x0000000000749356 in standard_ProcessUtility (pstmt=pstmt@entry=0x282b2c8, queryString=queryString@entry=0x2831398 "/* contrib/pg_stat_statements/pg_stat_statements--1.4.sql */\n\n-- complain if script is sourced in psql, rather than via CREATE EXTENSION\n\n\n-- Register functions.\nCREATE FUNCTION pg_stat_statements_res"..., context=context@entry=PROCESS_UTILITY_QUERY, params=params@entry=0x0, queryEnv=queryEnv@entry=0x0, dest=dest@entry=0xcf13a0 <donothingDR>, completionTag=completionTag@entry=0x0) at utility.c:923
#9  0x00007fddf8482025 in pgss_ProcessUtility (pstmt=0x282b2c8, queryString=0x2831398 "/* contrib/pg_stat_statements/pg_stat_statements--1.4.sql */\n\n-- complain if script is sourced in psql, rather than via CREATE EXTENSION\n\n\n-- Register functions.\nCREATE FUNCTION pg_stat_statements_res"..., context=PROCESS_UTILITY_QUERY, params=0x0, queryEnv=0x0, dest=0xcf13a0 <donothingDR>, completionTag=0x0) at pg_stat_statements.c:1005
#10 0x00000000005a708c in execute_sql_string (filename=0x281d7f0 "/usr/pgsql-11/share/extension/pg_stat_statements--1.4.sql", sql=0x2831398 "/* contrib/pg_stat_statements/pg_stat_statements--1.4.sql */\n\n-- complain if script is sourced in psql, rather than via CREATE EXTENSION\n\n\n-- Register functions.\nCREATE FUNCTION pg_stat_statements_res"...) at extension.c:763
#11 execute_extension_script (extensionOid=extensionOid@entry=24582, control=control@entry=0x282d2b0, from_version=from_version@entry=0x0, version=version@entry=0x281d368 "1.4", requiredSchemas=requiredSchemas@entry=0x0, schemaName=schemaName@entry=0x282ac68 "public", schemaOid=<optimized out>) at extension.c:924
#12 0x00000000005a7b0d in CreateExtensionInternal (extensionName=0x275c0c8 "pg_stat_statements", schemaName=0x282ac68 "public", schemaName@entry=0x0, versionName=0x281d368 "1.4", versionName@entry=0x0, oldVersionName=oldVersionName@entry=0x0, cascade=<optimized out>, parents=parents@entry=0x0, is_create=is_create@entry=true) at extension.c:1536
#13 0x00000000005a8017 in CreateExtension (pstate=pstate@entry=0x2814940, stmt=stmt@entry=0x275c0f8) at extension.c:1725
#14 0x000000000074a617 in ProcessUtilitySlow (pstate=pstate@entry=0x2814940, pstmt=pstmt@entry=0x275c1a8, queryString=queryString@entry=0x275b6e0 "create extension pg_stat_statements ;", context=context@entry=PROCESS_UTILITY_TOPLEVEL, params=params@entry=0x0, queryEnv=queryEnv@entry=0x0, completionTag=completionTag@entry=0x7fff47c0a8d0 "", dest=0x275c468) at utility.c:1392
#15 0x0000000000749356 in standard_ProcessUtility (pstmt=pstmt@entry=0x275c1a8, queryString=queryString@entry=0x275b6e0 "create extension pg_stat_statements ;", context=context@entry=PROCESS_UTILITY_TOPLEVEL, params=params@entry=0x0, queryEnv=queryEnv@entry=0x0, dest=dest@entry=0x275c468, completionTag=completionTag@entry=0x7fff47c0a8d0 "") at utility.c:923
#16 0x00007fddf8482025 in pgss_ProcessUtility (pstmt=0x275c1a8, queryString=0x275b6e0 "create extension pg_stat_statements ;", context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0, dest=0x275c468, completionTag=0x7fff47c0a8d0 "") at pg_stat_statements.c:1005
#17 0x0000000000746b96 in PortalRunUtility (portal=0x27c4860, pstmt=0x275c1a8, isTopLevel=<optimized out>, setHoldSnapshot=<optimized out>, dest=0x275c468, completionTag=0x7fff47c0a8d0 "") at pquery.c:1178
#18 0x00000000007475e7 in PortalRunMulti (portal=portal@entry=0x27c4860, isTopLevel=isTopLevel@entry=true, setHoldSnapshot=setHoldSnapshot@entry=false, dest=dest@entry=0x275c468, altdest=altdest@entry=0x275c468, completionTag=completionTag@entry=0x7fff47c0a8d0 "") at pquery.c:1331
#19 0x00000000007481d5 in PortalRun (portal=<optimized out>, count=9223372036854775807, isTopLevel=<optimized out>, run_once=<optimized out>, dest=0x275c468, altdest=0x275c468, completionTag=0x7fff47c0a8d0 "") at pquery.c:799
#20 0x0000000000744287 in exec_simple_query (query_string=<optimized out>) at postgres.c:1145
#21 0x0000000000745552 in PostgresMain (argc=<optimized out>, argv=<optimized out>, dbname=<optimized out>, username=<optimized out>) at postgres.c:4182
#22 0x0000000000480571 in BackendRun (port=0x277ad80) at postmaster.c:4358
#23 BackendStartup (port=0x277ad80) at postmaster.c:4030
#24 ServerLoop () at postmaster.c:1707
#25 0x00000000006d8639 in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x2756280) at postmaster.c:1380
#26 0x00000000004813cf in main (argc=3, argv=0x2756280) at main.c:228
(gdb) detach
Detaching from program: /usr/pgsql-11/bin/postgres, process 9599

On retrouve bien fmgr_info_cxt_security() sur le haut de la pile. Regardons de près la séquence ProcedureCreate() -> OidFunctionCall1Coll(), dans le code l’appel se passe de la manière suivante (pg_proc.c):

ObjectAddress
 ProcedureCreate(const char *procedureName,
(...)
        OidFunctionCall1(languageValidator, ObjectIdGetDatum(retval));
(...)

OidFunctionCall1() est un alias pointant sur OidFunctionCall1Coll() dans fmgr.h:

(...)
 #define OidFunctionCall1(functionId, arg1) \
     OidFunctionCall1Coll(functionId, InvalidOid, arg1)
(...)

et dans OidFunctionCall1Coll() dans fmgr.c, l’appel à fmgr_info() qui déclenche l’exception finale:

 Datum
 OidFunctionCall1Coll(Oid functionId, Oid collation, Datum arg1)
 {
     FmgrInfo    flinfo;
 
     fmgr_info(functionId, &flinfo);
 
     return FunctionCall1Coll(&flinfo, collation, arg1);
 }

Donc l’argument Oid functionId qui est égal à 1 et fait planter notre CREATE EXTENSION est une référence au départ à languageValidator, qui est une colonne de pg_language.

Dans les faits dans le catalogue système, la valeur de lanvalidator pour le langage ‘c’ qui est le langage de nos extensions, est à 1:

postgres=# select * from pg_language ;
 lanname  | lanowner | lanispl | lanpltrusted | lanplcallfoid | laninline | lanvalidator | lanacl
----------+----------+---------+--------------+---------------+-----------+--------------+--------
 internal |       10 | f       | f            |             0 |         0 |         2246 | NULL
 sql      |       10 | f       | t            |             0 |         0 |         2248 | NULL
 plpgsql  |       10 | t       | t            |         13868 |     13869 |        13870 | NULL
 c        |       10 | f       | f            |             0 |         0 |            1 | NULL
(4 rows)
Time: 5.114 ms

D’après la doc, le lanvalidator doit pointer vers la fonction de validation du langage lanname. Dans le cas du ‘c’, ce devrait être fmgr_c_validator:

postgres=# select oid, proname from pg_proc where proname='fmgr_c_validator' ;
 oid  |     proname      
------+------------------
 2247 | fmgr_c_validator
(1 ligne)

Au final si on update la colonne dans pg_language, le CREATE EXTENSION va fonctionner de nouveau:

postgres=# update pg_language set lanvalidator=2247 where lanname='c' ;
UPDATE 1
postgres=# create extension pg_stat_statements ;
CREATE EXTENSION

Mais la question reste de savoir pourquoi la valeur se retrouve à 1 en premier lieu. On s’est également rendu compte que lanvalidator était aussi à 1 dans template1 et le problème se propage à chaque nouvelle création de base. Il n’y a qu’un CREATE DATABASE … TEMPLATE template0 qui ne posera pas le problème.

Est-ce un problème au moment de l’initdb qui modifie cette valeur ? Toujours est-il que le problème n’est pas nouveau, plusieurs threads sur le forum général le mentionnent, notamment ici : https://www.postgresql.org/message-id/b7082510-b2a1-acbe-dc79-d4492eccacc4%40gmail.com

Affaire à suivre, bonne journée à toutes / tous, à+
David.

Continuez votre lecture sur le blog :

twitterlinkedinmail

David Baffaleuf

Laisser un commentaire

Votre adresse de messagerie ne sera pas publiée. Les champs obligatoires sont indiqués avec *

Ce site utilise Akismet pour réduire les indésirables. En savoir plus sur comment les données de vos commentaires sont utilisées.