citusdata / citusdata/pg_cron

pg_cron on Aurora cluster strange output

Open
#248 1 comment 0 reactions 0 assignees View on GitHub
Dominant language
C
Stars
3.9k
Forks
260
Avg merge
5d 5h
Merged PRs (30d)
1

Description

AWS Aurora Postresql pg_cron v1.4

I have an anonymous block where I call multiple procedures:

```
select cron.schedule ('load_asrs_snapshot','00 02 10 * *',$command$ do
$$
begin
call asrs_ga_supplement.ingest_asrs_ga_supplement_data();
call asrs_public.ingest_asrs_public_data();
end $$; $command$);

update cron.job
set database = 'feeds',
username = 'asrs'
where jobname = 'load_asrs_snapshot';
commit;
```

If I run the "command" outside of pg_cron, from psql, in the 'feeds' database as role 'asrs' I get something like this output:

```
feeds=> do
all asrsfeeds-> $$
feeds$> begin
feeds$> call asrs_ga_supplement.ingest_asrs_ga_supplement_data();
feeds$> call asrs_public.ingest_asrs_public_data();
feeds$> end $$;
INFO: analyzing "pg_temp_53.temp_all_items"
INFO: "temp_all_items": scanned 17278 of 17278 pages, containing 1546803 live rows and 0 dead rows; 30000 rows in sample, 1546803 estimated total rows
NOTICE: Table asrs_ga_supplement.all_items Rows Inserted: 1546803
NOTICE: Total load time: 00:02:19.303253
INFO: analyzing "pg_temp_53.temp_text"
INFO: "temp_text": scanned 7367 of 7367 pages, containing 57816 live rows and 0 dead rows; 30000 rows in sample, 57816 estimated total rows
NOTICE: Table asrs_ga_supplement.text Rows Inserted: 57816
NOTICE: Total load time: 00:00:18.410682
INFO: analyzing "pg_temp_53.temp_all_items"
INFO: "temp_all_items": scanned 30000 of 111057 pages, containing 2829978 live rows and 0 dead rows; 30000 rows in sample, 10476296 estimated total rows
NOTICE: Table asrs_public.all_items Rows Inserted: 10423030
NOTICE: Total load time: 00:18:05.223828
INFO: analyzing "pg_temp_53.temp_text"
INFO: "temp_text": scanned 30000 of 40242 pages, containing 350886 live rows and 0 dead rows; 30000 rows in sample, 470678 estimated total rows
NOTICE: Table asrs_public.text Rows Inserted: 469961
NOTICE: Total load time: 00:01:42.627377
DO

```

If I allow pg_cron to run this, I get in the postgresql log, in cloudwatch, abbreviated:
```
...

2023-03-08 14:17:22 UTC::@:[13556]:LOG: cron job 100: INFO: analyzing "pg_temp_51.temp_all_items" CONTEXT: SQL statement "ANALYZE VERBOSE temp_all_items" PL/pgSQL function ingest_asrs_ga_supplement_data() line 20 at SQL statement SQL statement "CALL asrs_ga_supplement.ingest_asrs_ga_supplement_data()" PL/pgSQL function inline_code_block line 3 at CALL
--
2023-03-08 14:17:22 UTC::@:[13556]:LOG: cron job 100: INFO: "temp_all_items": scanned 17278 of 17278 pages, containing 1546803 live rows and 0 dead rows; 30000 rows in sample, 1546803 estimated total rows CONTEXT: SQL statement "ANALYZE VERBOSE temp_all_items" PL/pgSQL function ingest_asrs_ga_supplement_data() line 20 at SQL statement SQL statement "CALL asrs_ga_supplement.ingest_asrs_ga_supplement_data()" PL/pgSQL function inline_code_block line 3 at CALL
2023-03-08 14:18:16 UTC::@:[13556]:LOG: cron job 100: NOTICE: Table asrs_ga_supplement.all_items Rows Inserted: 1546803 CONTEXT: PL/pgSQL function ingest_asrs_ga_supplement_data() line 36 at RAISE SQL statement "CALL asrs_ga_supplement.ingest_asrs_ga_supplement_data()" PL/pgSQL function inline_code_block line 3 at CALL
2023-03-08 14:18:16 UTC::@:[13556]:LOG: cron job 100: NOTICE: Total load time: 00:03:16.051938 CONTEXT: PL/pgSQL function ingest_asrs_ga_supplement_data() line 54 at RAISE SQL statement "CALL asrs_ga_supplement.ingest_asrs_ga_supplement_data()" PL/pgSQL function inline_code_block line 3 at CALL

...
```

It appears to be adding to the output a 'CONTEXT' error somehow. I have exception handling in each procedure and it never gets hit even when run from pg_cron.
Why am I getting this logging to the postgresql log? Any ideas?

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.