Skip to content

[YSQL][SQLsmith] ../../src/yb/rpc/proxy.cc:112] Timeout to wait resolve to complete #11302

@def-

Description

@def-

Jira Link: DB-764

Description

Debug logging, found with SQLsmith, can't reproduce. Similarly to #11301 it happens in the recovery handling after Trap:

TRAP: FailedAssertion("!(bms_is_subset(appendrel->lateral_relids, required_outer))", File: "../../../../../../../src/postgres/src/backend/optimizer/util/relnode.c", Line: 1543)
2022-02-01 14:42:55.406 CET [52434] LOG:  server process (PID 74783) was terminated by signal 6: Abort trap
2022-02-01 14:42:55.406 CET [52434] DETAIL:  Failed process was running: select  
	  ref_0.municipality as c0, 
	  pg_catalog.timestamp_larger(
	    cast(
	      pg_catalog.max(
	        cast(pg_catalog.timestamp(
	          cast(cast(null as "timestamp") as "timestamp"),
	          cast(ref_0.elevation_ft as int4)) as "timestamp")) over (partition by ref_0.local_code order by ref_0.municipality,ref_0.iso_region) as "timestamp"),
	    cast(
	      pg_catalog.min(
	        cast(case when cast(null as circle) &< cast(null as circle) then pg_catalog.timestamp_mi_interval(
	            cast(cast(null as "timestamp") as "timestamp"),
	            cast(cast(null as "interval") as "interval")) else pg_catalog.timestamp_mi_interval(
	            cast(cast(null as "timestamp") as "timestamp"),
	            cast(cast(null as "interval") as "interval")) end
	           as "timestamp")) over (partition by subq_0.c3,subq_0.c2 order by ref_0.elevation_ft,subq_0.c0) as "timestamp")) as c1, 
	  subq_2.c4 as c2, 
	  
	    pg_catalog.bit_or(
	      cast(cast(null as "bit") as "bit")) over (partition by subq_2.c2,sub
2022-02-01 14:42:55.406 CET [52434] LOG:  terminating any other active server processes
2022-02-01 14:42:55.406 CET [74784] WARNING:  terminating connection because of crash of another server process at character 929
2022-02-01 14:42:55.406 CET [74784] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2022-02-01 14:42:55.406 CET [74784] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2022-02-01 14:42:55.406 CET [74779] WARNING:  terminating connection because of crash of another server process
2022-02-01 14:42:55.406 CET [74779] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2022-02-01 14:42:55.406 CET [74779] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2022-02-01 14:42:55.406 CET [74785] WARNING:  terminating connection because of crash of another server process at character 420
2022-02-01 14:42:55.406 CET [74785] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2022-02-01 14:42:55.406 CET [74785] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2022-02-01 14:42:55.406 CET [74782] WARNING:  terminating connection because of crash of another server process
2022-02-01 14:42:55.406 CET [74782] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2022-02-01 14:42:55.406 CET [74782] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2022-02-01 14:42:55.406 CET [74781] WARNING:  terminating connection because of crash of another server process
2022-02-01 14:42:55.406 CET [74781] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2022-02-01 14:42:55.406 CET [74781] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2022-02-01 14:42:55.406 CET [74780] WARNING:  terminating connection because of crash of another server process
2022-02-01 14:42:55.406 CET [74780] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2022-02-01 14:42:55.406 CET [74780] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2022-02-01 14:42:55.407 CET [74778] WARNING:  terminating connection because of crash of another server process
2022-02-01 14:42:55.407 CET [74778] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2022-02-01 14:42:55.407 CET [74778] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
I0201 14:42:55.407413 1844883456 poller.cc:66] Poll stopped: Service unavailable (yb/rpc/scheduler.cc:80): Scheduler is shutting down (system error 58)
W0201 14:42:55.407449 1846030336 outbound_call.cc:131] Failed to schedule invoking callback on response for request yb.tserver.TabletServerService.Read to 127.0.0.1: Aborted (yb/rpc/thread_pool.cc:260): Service is shutting down
I0201 14:42:55.407577 1844883456 poller.cc:66] Poll stopped: Service unavailable (yb/rpc/scheduler.cc:80): Scheduler is shutting down (system error 58)
I0201 14:42:55.407660 1844883456 poller.cc:66] Poll stopped: Service unavailable (yb/rpc/scheduler.cc:80): Scheduler is shutting down (system error 58)
W0201 14:42:55.407750 1846030336 outbound_call.cc:131] Failed to schedule invoking callback on response for request yb.tserver.TabletServerService.Read to 127.0.0.1: Aborted (yb/rpc/thread_pool.cc:260): Service is shutting down
W0201 14:42:55.407488 1846030336 outbound_call.cc:131] Failed to schedule invoking callback on response for request yb.tserver.TabletServerService.Read to 127.0.0.1: Aborted (yb/rpc/thread_pool.cc:260): Service is shutting down
I0201 14:42:55.407487 1844883456 poller.cc:66] Poll stopped: Service unavailable (yb/rpc/scheduler.cc:80): Scheduler is shutting down (system error 58)
I0201 14:42:55.407579 1844883456 poller.cc:66] Poll stopped: Service unavailable (yb/rpc/scheduler.cc:80): Scheduler is shutting down (system error 58)
W0201 14:42:55.408020 1846030336 outbound_call.cc:131] Failed to schedule invoking callback on response for request yb.tserver.TabletServerService.Read to 127.0.0.1: Aborted (yb/rpc/thread_pool.cc:260): Service is shutting down
I0201 14:42:55.407788 1844883456 poller.cc:66] Poll stopped: Service unavailable (yb/rpc/scheduler.cc:80): Scheduler is shutting down (system error 58)
W0201 14:42:55.407930 1846030336 rpc.cc:179] Aborted (yb/rpc/rpc.cc:178): Failed to schedule: 0x000000013362d728 -> Read(tablet: 775ed9f6db2a4c7d9a1cc9ec099fa364, num_ops: 1, num_attempts: 2, txn: 00000000-0000-0000-0000-000000000000, subtxn: [none])
I0201 14:42:55.408026 1844883456 poller.cc:66] Poll stopped: Service unavailable (yb/rpc/scheduler.cc:80): Scheduler is shutting down (system error 58)
W0201 14:42:55.409157 1846030336 rpc.cc:179] Aborted (yb/rpc/rpc.cc:178): Failed to schedule: 0x00000001348207f8 -> Read(tablet: 00000000000000000000000000000000, num_ops: 1, num_attempts: 2, txn: 00000000-0000-0000-0000-000000000000, subtxn: [none])
W0201 14:42:55.409265 1846030336 rpc.cc:179] Aborted (yb/rpc/rpc.cc:178): Failed to schedule: 0x0000000133646918 -> Read(tablet: 775ed9f6db2a4c7d9a1cc9ec099fa364, num_ops: 1, num_attempts: 2, txn: 00000000-0000-0000-0000-000000000000, subtxn: [none])
W0201 14:42:55.409672 1846030336 rpc.cc:179] Aborted (yb/rpc/rpc.cc:178): Failed to schedule: 0x000000013362ebd8 -> Read(tablet: 775ed9f6db2a4c7d9a1cc9ec099fa364, num_ops: 1, num_attempts: 2, txn: 00000000-0000-0000-0000-000000000000, subtxn: [none])
2022-02-01 14:42:56.440 CET [74786] FATAL:  the database system is in recovery mode
2022-02-01 14:42:56.440 CET [74787] FATAL:  the database system is in recovery mode
2022-02-01 14:42:56.441 CET [74788] FATAL:  the database system is in recovery mode
2022-02-01 14:42:56.446 CET [74789] FATAL:  the database system is in recovery mode
2022-02-01 14:42:56.458 CET [74790] FATAL:  the database system is in recovery mode
2022-02-01 14:42:56.458 CET [74791] FATAL:  the database system is in recovery mode
2022-02-01 14:42:56.462 CET [74792] FATAL:  the database system is in recovery mode
2022-02-01 14:42:58.500 CET [74793] FATAL:  the database system is in recovery mode
2022-02-01 14:42:58.500 CET [74794] FATAL:  the database system is in recovery mode
2022-02-01 14:42:58.503 CET [74795] FATAL:  the database system is in recovery mode
2022-02-01 14:42:58.510 CET [74796] FATAL:  the database system is in recovery mode
2022-02-01 14:42:58.514 CET [74797] FATAL:  the database system is in recovery mode
2022-02-01 14:42:58.535 CET [74798] FATAL:  the database system is in recovery mode
2022-02-01 14:42:58.553 CET [74799] FATAL:  the database system is in recovery mode
F0201 14:43:00.408491 48530816 proxy.cc:112] Timeout to wait resolve to complete
Fatal failure details written to /Users/deen/var/data/yb-data/tserver/logs/yb-tserver.FATAL.details.2022-02-01T14_43_00.pid74785.txt
F20220201 14:43:00 ../../src/yb/rpc/proxy.cc:112] Timeout to wait resolve to complete
    @        0x10687d894  google::LogDestination::LogToSinks()
    @        0x10687c9cc  google::LogMessage::SendToLog()
    @        0x10687d388  google::LogMessage::Flush()
    @        0x10687d19c  google::LogMessage::~LogMessage()
    @        0x10f7976dc  yb::rpc::Proxy::~Proxy()
    @        0x10f797954  yb::rpc::Proxy::~Proxy()
    @        0x10f7a84cc  std::__1::default_delete<>::operator()()
    @        0x10f7a9940  std::__1::__shared_ptr_pointer<>::__on_zero_shared()
    @        0x104076910  std::__1::__shared_count::__release_shared()
    @        0x1040768c0  std::__1::__shared_weak_count::__release_shared()
    @        0x104076894  std::__1::shared_ptr<>::~shared_ptr()
    @        0x104076280  std::__1::shared_ptr<>::~shared_ptr()
    @        0x1040aae6c  std::__1::pair<>::~pair()
    @        0x1040aae3c  std::__1::pair<>::~pair()
    @        0x1040aad48  std::__1::allocator_traits<>::destroy<>()
    @        0x1040aac90  std::__1::__hash_table<>::__deallocate_node()
    @        0x1040aac10  std::__1::__hash_table<>::~__hash_table()
    @        0x1040aabd0  std::__1::__hash_table<>::~__hash_table()
    @        0x1040aaba4  std::__1::unordered_map<>::~unordered_map()
    @        0x1040aa800  std::__1::unordered_map<>::~unordered_map()
    @        0x1040aa79c  yb::rpc::ProxyCache::~ProxyCache()
    @        0x1040aa754  yb::rpc::ProxyCache::~ProxyCache()
    @        0x1040aa6fc  std::__1::default_delete<>::operator()()
    @        0x1040aa680  std::__1::unique_ptr<>::reset()
    @        0x1040aa614  std::__1::unique_ptr<>::~unique_ptr()
    @        0x10408ef54  std::__1::unique_ptr<>::~unique_ptr()
    @        0x1040903a0  yb::pggate::PgApiImpl::~PgApiImpl()
    @        0x1040904d0  yb::pggate::PgApiImpl::~PgApiImpl()
    @        0x1040904fc  yb::pggate::PgApiImpl::~PgApiImpl()
    @        0x10406b3ec  YBCDestroyPgGate
    @        0x10276dbb8  YBOnPostgresBackendShutdown
    @        0x102561928  quickdie

*** Check failure stack trace: ***
    @        0x10687cb8c  google::LogMessage::SendToLog()
    @        0x10687d388  google::LogMessage::Flush()
    @        0x10687d19c  google::LogMessage::~LogMessage()
    @        0x10f7976dc  yb::rpc::Proxy::~Proxy()
    @        0x10f797954  yb::rpc::Proxy::~Proxy()
    @        0x10f7a84cc  std::__1::default_delete<>::operator()()
    @        0x10f7a9940  std::__1::__shared_ptr_pointer<>::__on_zero_shared()
    @        0x104076910  std::__1::__shared_count::__release_shared()
    @        0x1040768c0  std::__1::__shared_weak_count::__release_shared()
    @        0x104076894  std::__1::shared_ptr<>::~shared_ptr()
    @        0x104076280  std::__1::shared_ptr<>::~shared_ptr()
    @        0x1040aae6c  std::__1::pair<>::~pair()
    @        0x1040aae3c  std::__1::pair<>::~pair()
    @        0x1040aad48  std::__1::allocator_traits<>::destroy<>()
    @        0x1040aac90  std::__1::__hash_table<>::__deallocate_node()
    @        0x1040aac10  std::__1::__hash_table<>::~__hash_table()
    @        0x1040aabd0  std::__1::__hash_table<>::~__hash_table()
    @        0x1040aaba4  std::__1::unordered_map<>::~unordered_map()
    @        0x1040aa800  std::__1::unordered_map<>::~unordered_map()
    @        0x1040aa79c  yb::rpc::ProxyCache::~ProxyCache()
    @        0x1040aa754  yb::rpc::ProxyCache::~ProxyCache()
    @        0x1040aa6fc  std::__1::default_delete<>::operator()()
    @        0x1040aa680  std::__1::unique_ptr<>::reset()
    @        0x1040aa614  std::__1::unique_ptr<>::~unique_ptr()
    @        0x10408ef54  std::__1::unique_ptr<>::~unique_ptr()
    @        0x1040903a0  yb::pggate::PgApiImpl::~PgApiImpl()
    @        0x1040904d0  yb::pggate::PgApiImpl::~PgApiImpl()
    @        0x1040904fc  yb::pggate::PgApiImpl::~PgApiImpl()
    @        0x10406b3ec  YBCDestroyPgGate
    @        0x10276dbb8  YBOnPostgresBackendShutdown
    @        0x102561928  quickdie
    @        0x199ab44e4  _sigtramp

Metadata

Metadata

Assignees

Labels

area/ysqlYugabyte SQL (YSQL)kind/bugThis issue is a bugkind/failing-testTests and testing infrapriority/mediumMedium priority issueqa_automationBugs identified via itest-system, LST, Stress automation or causing automation failures

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions