Обсуждение: cache lookup failed for function 1 on fmgr_info_cxt_security,fmgr.c:184
Hello All, CentOS Linux release 7.5.1804 (Core) Postgres 10.7. When "create extension "uuid-ossp"", I got : 2019-04-22 02:41:53.323 UTC [10305] XX000ERROR: XX000: cache lookup failed for function 1 2019-04-22 02:41:53.323 UTC [10305] XX000LOCATION: fmgr_info_cxt_security, fmgr.c:184 2019-04-22 02:41:53.323 UTC [10305] XX000STATEMENT: create extension "uuid-ossp" ; I tried reinstall contrib module and even all postgres component, but still no luck. Try restarting the server also but no luck. Any idea how to resolve this ? Thanks, Soni
Soni <diptatapa@gmail.com> writes: > When "create extension "uuid-ossp"", I got : > 2019-04-22 02:41:53.323 UTC [10305] XX000ERROR: XX000: cache lookup > failed for function 1 > 2019-04-22 02:41:53.323 UTC [10305] XX000LOCATION: > fmgr_info_cxt_security, fmgr.c:184 > 2019-04-22 02:41:53.323 UTC [10305] XX000STATEMENT: create extension > "uuid-ossp" ; That is just bizarre. uuid-ossp's installation script does nothing beyond a few simple CREATE FUNCTION commands, so it's really hard to see how you could be getting to an incorrect function call. Do you perhaps have any other extensions installed that could be running add-on code during DDL commands? I'm thinking of pgaudit or auto_explain or the like. If so, try disabling those to see if the problem goes away. If that's not it, could we trouble you to get a stack trace of this problem? Set a breakpoint at errfinish, run the CREATE EXTENSION, and when it stops send us the output of "bt". (Make sure that fmgr_info_cxt_security appears one or two levels down in the trace, else you stopped at the wrong message output.) https://wiki.postgresql.org/wiki/Generating_a_stack_trace_of_a_PostgreSQL_backend regards, tom lane
On 4/21/19 9:14 PM, Soni wrote: > Hello All, > > CentOS Linux release 7.5.1804 (Core) > Postgres 10.7. > > When "create extension "uuid-ossp"", I got : > 2019-04-22 02:41:53.323 UTC [10305] XX000ERROR: XX000: cache lookup > failed for function 1 > 2019-04-22 02:41:53.323 UTC [10305] XX000LOCATION: > fmgr_info_cxt_security, fmgr.c:184 > 2019-04-22 02:41:53.323 UTC [10305] XX000STATEMENT: create extension > "uuid-ossp" ; > I tried reinstall contrib module and even all postgres component, but > still no luck. > Try restarting the server also but no luck. > Any idea how to resolve this ? How and where are you installing Postgres and -contrib from? Is the user you are running CREATE EXTENSION a superuser? > > Thanks, > Soni > > > -- Adrian Klaver adrian.klaver@aklaver.com
I install the contrib module from the postgres repo using yum install. creating extension run as postgres superuser. Thanks, Soni On 22/04/2019 21:05, Adrian Klaver wrote: > On 4/21/19 9:14 PM, Soni wrote: >> Hello All, >> >> CentOS Linux release 7.5.1804 (Core) >> Postgres 10.7. >> >> When "create extension "uuid-ossp"", I got : >> 2019-04-22 02:41:53.323 UTC [10305] XX000ERROR: XX000: cache lookup >> failed for function 1 >> 2019-04-22 02:41:53.323 UTC [10305] XX000LOCATION: >> fmgr_info_cxt_security, fmgr.c:184 >> 2019-04-22 02:41:53.323 UTC [10305] XX000STATEMENT: create extension >> "uuid-ossp" ; >> I tried reinstall contrib module and even all postgres component, but >> still no luck. >> Try restarting the server also but no luck. >> Any idea how to resolve this ? > > How and where are you installing Postgres and -contrib from? > > Is the user you are running CREATE EXTENSION a superuser? > >> >> Thanks, >> Soni >> >> >> > >
We have no other extensions installed, just plpgsql. Here's the backtrace. Please let me know if it helps. #0 errfinish (dummy=dummy@entry=0) at elog.c:414 #1 0x0000000000820068 in elog_finish (elevel=elevel@entry=20, fmt=fmt@entry=0x864278 "cache lookup failed for function %u") at elog.c:1376 #2 0x0000000000821e63 in fmgr_info_cxt_security (functionId=1, functionId@entry=18230952, finfo=finfo@entry=0x7ffcd9090460, mcxt=<optimized out>, ignore_security=ignore_security@entry=0 '\000') at fmgr.c:184 #3 0x00000000008233f2 in fmgr_info (finfo=0x7ffcd9090460, functionId=18230952) at fmgr.c:129 #4 OidFunctionCall1Coll (functionId=functionId@entry=1, collation=collation@entry=0, arg1=arg1@entry=75471) at fmgr.c:1325 #5 0x0000000000532054 in ProcedureCreate (procedureName=<optimized out>, procNamespace=procNamespace@entry=2200, replace=<optimized out>, returnsSet=returnsSet@entry=0 '\000', returnType=returnType@entry=2950, proowner=10, languageObjectId=languageObjectId@entry=13, languageValidator=languageValidator@entry=1, prosrc=prosrc@entry=0x1139fb0 "uuid_nil", probin=probin@entry=0x1139f80 "$libdir/uuid-ossp", isAgg=isAgg@entry=0 '\000', isWindowFunc=isWindowFunc@entry=0 '\000', security_definer=security_definer@entry=0 '\000', isLeakProof=isLeakProof@entry=0 '\000', isStrict=isStrict@entry=1 '\001', volatility=volatility@entry=105 'i', parallel=parallel@entry=115 's', parameterTypes=parameterTypes@entry=0x1162e90, 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:714 #6 0x00000000005a3a2e in CreateFunction (pstate=pstate@entry=0x1133990, stmt=stmt@entry=0x113a250) at functioncmds.c:1083 #7 0x0000000000720967 in ProcessUtilitySlow (pstate=pstate@entry=0x1133990, pstmt=pstmt@entry=0x1149698, queryString=queryString@entry=0x113fb38 "/* contrib/uuid-ossp/uuid-ossp--1.1.sql */\n\n-- complain if script is sourced in psql, rather than via CREATE EXTENSION\n\n\nCREATE FUNCTION uuid_nil()\nRETURNS uuid\nAS '$libdir/uuid-ossp', 'uuid_nil'\nIMMU"..., context=context@entry=PROCESS_UTILITY_QUERY, params=params@entry=0x0, queryEnv=queryEnv@entry=0x0, completionTag=completionTag@entry=0x0, dest=0xca42a0 <donothingDR>) at utility.c:1433 #8 0x000000000071fa6f in standard_ProcessUtility (pstmt=0x1149698, queryString=0x113fb38 "/* contrib/uuid-ossp/uuid-ossp--1.1.sql */\n\n-- complain if script is sourced in psql, rather than via CREATE EXTENSION\n\n\nCREATE FUNCTION uuid_nil()\nRETURNS uuid\nAS '$libdir/uuid-ossp', 'uuid_nil'\nIMMU"..., context=PROCESS_UTILITY_QUERY, params=0x0, queryEnv=0x0, dest=0xca42a0 <donothingDR>, completionTag=0x0) at utility.c:931 #9 0x000000000059a6ac in execute_sql_string (filename=0x112bc18 "/usr/pgsql-10/share/extension/uuid-ossp--1.1.sql", sql=0x113fb38 "/* contrib/uuid-ossp/uuid-ossp--1.1.sql */\n\n-- complain if script is sourced in psql, rather than via CREATE EXTENSION\n\n\nCREATE FUNCTION uuid_nil()\nRETURNS uuid\nAS '$libdir/uuid-ossp', 'uuid_nil'\nIMMU"...) at extension.c:763 #10 execute_extension_script (extensionOid=extensionOid@entry=75470, control=control@entry=0x112c310, from_version=from_version@entry=0x0, version=version@entry=0x1132b78 "1.1", requiredSchemas=requiredSchemas@entry=0x0, schemaName=schemaName@entry=0x112c2f8 "public", schemaOid=<optimized out>) at extension.c:924 #11 0x000000000059b135 in CreateExtensionInternal (extensionName=0x10fa100 "uuid-ossp", schemaName=0x112c2f8 "public", schemaName@entry=0x0, versionName=0x1132b78 "1.1", versionName@entry=0x0, oldVersionName=oldVersionName@entry=0x0, cascade=<optimized out>, parents=parents@entry=0x0, is_create=is_create@entry=1 '\001') at extension.c:1536 #12 0x000000000059b647 in CreateExtension (pstate=pstate@entry=0x1149428, stmt=stmt@entry=0x10fa120) at extension.c:1725 #13 0x0000000000720cdf in ProcessUtilitySlow (pstate=pstate@entry=0x1149428, pstmt=pstmt@entry=0x10fa440, queryString=queryString@entry=0x10f9738 "create extension \"uuid-ossp\" ;", context=context@entry=PROCESS_UTILITY_TOPLEVEL, params=params@entry=0x0, queryEnv=queryEnv@entry=0x0, completionTag=completionTag@entry=0x7ffcd9091930 "", dest=0x10fa520) at utility.c:1352 #14 0x000000000071fa6f in standard_ProcessUtility (pstmt=0x10fa440, queryString=0x10f9738 "create extension \"uuid-ossp\" ;", context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0, dest=0x10fa520, completionTag=0x7ffcd9091930 "") at utility.c:931 #15 0x000000000071d368 in PortalRunUtility (portal=0x114a4c8, pstmt=0x10fa440, isTopLevel=<optimized out>, setHoldSnapshot=<optimized out>, dest=0x10fa520, completionTag=0x7ffcd9091930 "") at pquery.c:1178 #16 0x000000000071dda7 in PortalRunMulti (portal=portal@entry=0x114a4c8, isTopLevel=isTopLevel@entry=1 '\001', setHoldSnapshot=setHoldSnapshot@entry=0 '\000', ---Type <return> to continue, or q <return> to quit--- dest=dest@entry=0x10fa520, altdest=altdest@entry=0x10fa520, completionTag=completionTag@entry=0x7ffcd9091930 "") at pquery.c:1331 #17 0x000000000071e995 in PortalRun (portal=<optimized out>, count=9223372036854775807, isTopLevel=<optimized out>, run_once=<optimized out>, dest=0x10fa520, altdest=0x10fa520, completionTag=0x7ffcd9091930 "") at pquery.c:799 #18 0x000000000071aa13 in exec_simple_query (query_string=<optimized out>) at postgres.c:1122 #19 0x000000000071bd0c in PostgresMain (argc=<optimized out>, argv=<optimized out>, dbname=<optimized out>, username=<optimized out>) at postgres.c:4117 #20 0x000000000047b246 in BackendRun (port=0x1098a20) at postmaster.c:4405 #21 BackendStartup (port=0x1098a20) at postmaster.c:4077 #22 ServerLoop () at postmaster.c:1755 #23 0x00000000006b25ef in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x1070bc0) at postmaster.c:1363 #24 0x000000000047c06f in main (argc=3, argv=0x1070bc0) at main.c:228 Thanks, Soni On 22/04/2019 21:04, Tom Lane wrote: > Soni <diptatapa@gmail.com> writes: >> When "create extension "uuid-ossp"", I got : >> 2019-04-22 02:41:53.323 UTC [10305] XX000ERROR: XX000: cache lookup >> failed for function 1 >> 2019-04-22 02:41:53.323 UTC [10305] XX000LOCATION: >> fmgr_info_cxt_security, fmgr.c:184 >> 2019-04-22 02:41:53.323 UTC [10305] XX000STATEMENT: create extension >> "uuid-ossp" ; > That is just bizarre. uuid-ossp's installation script does nothing > beyond a few simple CREATE FUNCTION commands, so it's really hard to > see how you could be getting to an incorrect function call. > > Do you perhaps have any other extensions installed that could be > running add-on code during DDL commands? I'm thinking of pgaudit > or auto_explain or the like. If so, try disabling those to see > if the problem goes away. > > If that's not it, could we trouble you to get a stack trace of > this problem? Set a breakpoint at errfinish, run the CREATE > EXTENSION, and when it stops send us the output of "bt". > (Make sure that fmgr_info_cxt_security appears one or two levels > down in the trace, else you stopped at the wrong message output.) > > https://wiki.postgresql.org/wiki/Generating_a_stack_trace_of_a_PostgreSQL_backend > > regards, tom lane
On Tue, 2019-04-23 at 09:15 +0700, Soni wrote: > I install the contrib module from the postgres repo using yum > install. > creating extension run as postgres superuser. > > Thanks, > Soni > 1) Is there a uuid-ossp.control file sitting in the $SHAREDIR/extension path? 2) Does its name exist in pg_available_extensions? 3) Is there a uuid-ossp.so in the lib path? My 2 cents. Cheers Rob > On 22/04/2019 21:05, Adrian Klaver wrote: > > On 4/21/19 9:14 PM, Soni wrote: > > > Hello All, > > > > > > CentOS Linux release 7.5.1804 (Core) > > > Postgres 10.7. > > > > > > When "create extension "uuid-ossp"", I got : > > > 2019-04-22 02:41:53.323 UTC [10305] XX000ERROR: XX000: cache > > > lookup > > > failed for function 1 > > > 2019-04-22 02:41:53.323 UTC [10305] XX000LOCATION: > > > fmgr_info_cxt_security, fmgr.c:184 > > > 2019-04-22 02:41:53.323 UTC [10305] XX000STATEMENT: create > > > extension > > > "uuid-ossp" ; > > > I tried reinstall contrib module and even all postgres component, > > > but > > > still no luck. > > > Try restarting the server also but no luck. > > > Any idea how to resolve this ? > > > > How and where are you installing Postgres and -contrib from? > > > > Is the user you are running CREATE EXTENSION a superuser? > > > > > Thanks, > > > Soni > > > > > > > > > > >
Yes for that three questions. -bash-4.2$ ls /usr/pgsql-10/share/extension/uuid-ossp.control /usr/pgsql-10/share/extension/uuid-ossp.control select * from pg_available_extensions where name = 'uuid-ossp'; name | default_version | installed_version | comment -----------+-----------------+-------------------+------------------------------------------------- uuid-ossp | 1.1 | | generate universally unique identifiers (UUIDs) (1 row) -bash-4.2$ ls /usr/pgsql-10/lib/uuid-ossp.so /usr/pgsql-10/lib/uuid-ossp.so Thanks, Soni On 23/04/2019 10:05, rob stone wrote: > > On Tue, 2019-04-23 at 09:15 +0700, Soni wrote: >> I install the contrib module from the postgres repo using yum >> install. >> creating extension run as postgres superuser. >> >> Thanks, >> Soni >> > 1) Is there a uuid-ossp.control file sitting in the $SHAREDIR/extension > path? > > 2) Does its name exist in pg_available_extensions? > > 3) Is there a uuid-ossp.so in the lib path? > > My 2 cents. > > Cheers > Rob > > > >> On 22/04/2019 21:05, Adrian Klaver wrote: >>> On 4/21/19 9:14 PM, Soni wrote: >>>> Hello All, >>>> >>>> CentOS Linux release 7.5.1804 (Core) >>>> Postgres 10.7. >>>> >>>> When "create extension "uuid-ossp"", I got : >>>> 2019-04-22 02:41:53.323 UTC [10305] XX000ERROR: XX000: cache >>>> lookup >>>> failed for function 1 >>>> 2019-04-22 02:41:53.323 UTC [10305] XX000LOCATION: >>>> fmgr_info_cxt_security, fmgr.c:184 >>>> 2019-04-22 02:41:53.323 UTC [10305] XX000STATEMENT: create >>>> extension >>>> "uuid-ossp" ; >>>> I tried reinstall contrib module and even all postgres component, >>>> but >>>> still no luck. >>>> Try restarting the server also but no luck. >>>> Any idea how to resolve this ? >>> How and where are you installing Postgres and -contrib from? >>> >>> Is the user you are running CREATE EXTENSION a superuser? >>> >>>> Thanks, >>>> Soni >>>> >>>> >>>> >>
Soni <diptatapa@gmail.com> writes:
> Here's the backtrace. Please let me know if it helps.
> #4 OidFunctionCall1Coll (functionId=functionId@entry=1,
> collation=collation@entry=0, arg1=arg1@entry=75471) at fmgr.c:1325
hm, there's "function 1" ...
> #5 0x0000000000532054 in ProcedureCreate (procedureName=<optimized
> out>, procNamespace=procNamespace@entry=2200, replace=<optimized out>,
> returnsSet=returnsSet@entry=0 '\000',
> returnType=returnType@entry=2950, proowner=10,
> languageObjectId=languageObjectId@entry=13,
> languageValidator=languageValidator@entry=1,
... and that's where it's coming from. Seems like you have corrupt
data in pg_language. Might be entertaining to see what
"select * from pg_language" gives.
regards, tom lane
Here it is: select * from pg_language; lanname | lanowner | lanispl | lanpltrusted | lanplcallfoid | laninline | lanvalidator | lanacl ----------+----------+---------+--------------+---------------+-----------+--------------+-------- internal | 10 | f | f | 0 | 0 | 2246 | sql | 10 | f | t | 0 | 0 | 2248 | plpgsql | 10 | t | t | 13793 | 13794 | 13795 | c | 10 | f | f | 0 | 0 | 1 | (4 rows) Thanks, Soni On 23/04/2019 10:31, Tom Lane wrote: > Soni <diptatapa@gmail.com> writes: >> Here's the backtrace. Please let me know if it helps. >> #4 OidFunctionCall1Coll (functionId=functionId@entry=1, >> collation=collation@entry=0, arg1=arg1@entry=75471) at fmgr.c:1325 > hm, there's "function 1" ... > >> #5 0x0000000000532054 in ProcedureCreate (procedureName=<optimized >> out>, procNamespace=procNamespace@entry=2200, replace=<optimized out>, >> returnsSet=returnsSet@entry=0 '\000', >> returnType=returnType@entry=2950, proowner=10, >> languageObjectId=languageObjectId@entry=13, >> languageValidator=languageValidator@entry=1, > ... and that's where it's coming from. Seems like you have corrupt > data in pg_language. Might be entertaining to see what > "select * from pg_language" gives. > > regards, tom lane
Fix it, change the lanvalidator value of 1 to the value of fmgr_c_validator. Thanks a lot Tom, that was fantastic. Not sure how the lanvalidator value changed to 1. Thanks, Soni On 23/04/2019 10:39, Soni wrote: > Here it is: > > select * from pg_language; > lanname | lanowner | lanispl | lanpltrusted | lanplcallfoid | > laninline | lanvalidator | lanacl > ----------+----------+---------+--------------+---------------+-----------+--------------+-------- > > internal | 10 | f | f | 0 > | 0 | 2246 | > sql | 10 | f | t | 0 > | 0 | 2248 | > plpgsql | 10 | t | t | 13793 | > 13794 | 13795 | > c | 10 | f | f | 0 > | 0 | 1 | > (4 rows) > > Thanks, > Soni > > On 23/04/2019 10:31, Tom Lane wrote: >> Soni <diptatapa@gmail.com> writes: >>> Here's the backtrace. Please let me know if it helps. >>> #4 OidFunctionCall1Coll (functionId=functionId@entry=1, >>> collation=collation@entry=0, arg1=arg1@entry=75471) at fmgr.c:1325 >> hm, there's "function 1" ... >> >>> #5 0x0000000000532054 in ProcedureCreate (procedureName=<optimized >>> out>, procNamespace=procNamespace@entry=2200, replace=<optimized out>, >>> returnsSet=returnsSet@entry=0 '\000', >>> returnType=returnType@entry=2950, proowner=10, >>> languageObjectId=languageObjectId@entry=13, >>> languageValidator=languageValidator@entry=1, >> ... and that's where it's coming from. Seems like you have corrupt >> data in pg_language. Might be entertaining to see what >> "select * from pg_language" gives. >> >> regards, tom lane
Soni <diptatapa@gmail.com> writes:
> Here it is:
> select * from pg_language;
> lanname | lanowner | lanispl | lanpltrusted | lanplcallfoid |
> laninline | lanvalidator | lanacl
> ----------+----------+---------+--------------+---------------+-----------+--------------+--------
> internal | 10 | f | f | 0 |
> 0 | 2246 |
> sql | 10 | f | t | 0 |
> 0 | 2248 |
> plpgsql | 10 | t | t | 13793 |
> 13794 | 13795 |
> c | 10 | f | f | 0 |
> 0 | 1 |
> (4 rows)
Hm. That doesn't look like data corruption: that looks like
somebody actually did
update pg_language set lanvalidator = 1 where lanname = 'c';
or something equivalent to that. Needless to say, that was
not a good idea.
You said you reinstalled the postgres executables, but did you
re-initdb? Or even just re-create the current database?
I'm wondering if it's like that in every database of your cluster.
It'd be possible to fix this particular database by setting
lanvalidator back to its correct value (2247) but it'd be
wise to first inquire as to how it got like this.
regards, tom lane
I did not re-initdb, just use the old pgdata. I also did not recreate current database. Some of the database has value 1 for lanvalidator, some has 2247. I'll check with the team how the lanvalidator got 1 for the value. I will report back here. Thanks, Soni. On 23/04/2019 10:51, Tom Lane wrote: > Soni <diptatapa@gmail.com> writes: >> Here it is: >> select * from pg_language; >> lanname | lanowner | lanispl | lanpltrusted | lanplcallfoid | >> laninline | lanvalidator | lanacl >> ----------+----------+---------+--------------+---------------+-----------+--------------+-------- >> internal | 10 | f | f | 0 | >> 0 | 2246 | >> sql | 10 | f | t | 0 | >> 0 | 2248 | >> plpgsql | 10 | t | t | 13793 | >> 13794 | 13795 | >> c | 10 | f | f | 0 | >> 0 | 1 | >> (4 rows) > Hm. That doesn't look like data corruption: that looks like > somebody actually did > > update pg_language set lanvalidator = 1 where lanname = 'c'; > > or something equivalent to that. Needless to say, that was > not a good idea. > > You said you reinstalled the postgres executables, but did you > re-initdb? Or even just re-create the current database? > I'm wondering if it's like that in every database of your cluster. > > It'd be possible to fix this particular database by setting > lanvalidator back to its correct value (2247) but it'd be > wise to first inquire as to how it got like this. > > regards, tom lane