search

noxxi / p5-net-sip

Net::SIP Perl Module
Other
15 stars 22 forks source link

Fix calling error callbacks when TCP connect timeout happens #41

Closed pali closed 3 years ago

pali commented 3 years ago

Fix calling error callbacks when TCP connect timeout happens

When destination TCP port is unreachable and connect timeout occurs then Net::SIP does not call error callback and stay stuck:

1617461505.8622 DEBUG:<40> Net::SIP::SocketPool::sendto[257]: need new tcp socket to DST_IP:DST_PORT
1617461505.8624 DEBUG:<99> Net::SIP::SocketPool::_timeout_sockets[309]: timeout sockets
1617461505.8624 DEBUG:<99> Net::SIP::SocketPool::_timeout_sockets[326]: timeout sockets - need timer
1617461505.8625 DEBUG:<100> Net::SIP::SocketPool::_tcp_connect[559]: tcp connect: Operation now in progress
1617461505.8625 DEBUG:<100> Net::SIP::SocketPool::_tcp_connect[569]: tcp connect: add write handler for async connect
1617461505.8626 DEBUG:<99> Net::SIP::Dispatcher::Eventloop::addFD[61]: Net::SIP::Dispatcher::Eventloop=HASH(0x55b88997fd10) added fn=4 rw(1) sock=SRC_IP:SRC_PORT
1617461505.8626 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::addFD[64]: maxfd=5
1617461505.8626 DEBUG:<100> Net::SIP::Dispatcher::cancel_delivery[458]: cancel packet id: 909c0ac295d253f5d044b609795739af 1
1617461505.8627 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[156]: timeout = <undef>
1617461505.8627 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[188]: timeout = 0.961836099624634
1617461505.8627 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[198]: BEFORE read=00010000 write=00001000
1617461506.8257 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[201]: AFTER  read=00000000 write=00000000 nfound=0
1617461506.8259 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[156]: timeout = <undef>
1617461506.8260 DEBUG:<50> Net::SIP::Dispatcher::Eventloop::loop[172]: trigger timer(disp_expire) 1617461506.82242 repeat=1
1617461506.8262 DEBUG:<50> Net::SIP::Dispatcher::queue_expire[576]: next expire <undef>
1617461506.8263 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[188]: timeout = 7.03477001190186
1617461506.8264 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[198]: BEFORE read=00010000 write=00001000
1617461513.8652 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[201]: AFTER  read=00000000 write=00000000 nfound=0
1617461513.8653 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[156]: timeout = <undef>
1617461513.8653 DEBUG:<50> Net::SIP::Dispatcher::Eventloop::loop[172]: trigger timer(socketpool-timeout) 1617461513.86058 repeat=8
1617461513.8654 DEBUG:<99> Net::SIP::SocketPool::_timeout_sockets[309]: timeout sockets
1617461513.8655 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[176]: timer(socketpool-timeout) gets repeated at 1617461521
1617461513.8656 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[188]: timeout = 7.99535298347473
1617461513.8656 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[198]: BEFORE read=00010000 write=00001000
1617461521.8691 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[201]: AFTER  read=00000000 write=00000000 nfound=0
1617461521.8692 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[156]: timeout = <undef>
1617461521.8693 DEBUG:<50> Net::SIP::Dispatcher::Eventloop::loop[172]: trigger timer(socketpool-timeout) 1617461521.86058 repeat=8
1617461521.8693 DEBUG:<99> Net::SIP::SocketPool::_timeout_sockets[309]: timeout sockets
1617461521.8694 DEBUG:<1> Net::SIP::SocketPool::_error[345]: connect timed out
1617461521.8695 DEBUG:<99> Net::SIP::Dispatcher::Eventloop::delFD[80]: Net::SIP::Dispatcher::Eventloop=HASH(0x55b88997fd10) delete fn=4 sock=SRC_IP:SRC_PORT
1617461521.8696 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::delFD[99]: maxfd=4
1617461521.8697 DEBUG:<99> Net::SIP::SocketPool::_timeout_sockets[336]: timer cancel
1617461521.8697 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[188]: timeout = <undef>
1617461521.8698 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[198]: BEFORE read=00010000 write=00000000

It can happen during calling $ua->register() and this issue cause that $ua->register() never finish and never call its (error) callback.

Fix this issue by explicitly calling invoke_callback() with required error callback with errno ETIMEDOUT from method _timeout_sockets().

After this change Net::SIP::Simple recognize connection timeout error:

1617570630.2355 DEBUG:<40> Net::SIP::SocketPool::sendto[258]: need new tcp socket to DST_IP:DST_PORT
1617570630.2357 DEBUG:<99> Net::SIP::SocketPool::_timeout_sockets[310]: timeout sockets
1617570630.2358 DEBUG:<99> Net::SIP::SocketPool::_timeout_sockets[329]: timeout sockets - need timer
1617570630.2359 DEBUG:<100> Net::SIP::SocketPool::_tcp_connect[562]: tcp connect: Operation now in progress
1617570630.2359 DEBUG:<100> Net::SIP::SocketPool::_tcp_connect[572]: tcp connect: add write handler for async connect
1617570630.2359 DEBUG:<99> Net::SIP::Dispatcher::Eventloop::addFD[61]: Net::SIP::Dispatcher::Eventloop=HASH(0x5635aea06ad0) added fn=4 rw(1) sock=SRC_IP:SRC_PORT
1617570630.2360 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::addFD[64]: maxfd=5
1617570630.2360 DEBUG:<100> Net::SIP::Dispatcher::cancel_delivery[458]: cancel packet id: f0fd78ed3bcb64b23f021ad05ae43d70 1
1617570630.2360 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[156]: timeout = <undef>
1617570630.2360 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[188]: timeout = 0.997897148132324
1617570630.2361 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[198]: BEFORE read=00010000 write=00001000
1617570631.2351 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[201]: AFTER  read=00000000 write=00000000 nfound=0
1617570631.2353 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[156]: timeout = <undef>
1617570631.2353 DEBUG:<50> Net::SIP::Dispatcher::Eventloop::loop[172]: trigger timer(disp_expire) 1617570631.23391 repeat=1
1617570631.2354 DEBUG:<50> Net::SIP::Dispatcher::queue_expire[576]: next expire <undef>
1617570631.2355 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[188]: timeout = 6.99869799613953
1617570631.2355 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[198]: BEFORE read=00010000 write=00001000
1617570638.2415 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[201]: AFTER  read=00000000 write=00000000 nfound=0
1617570638.2416 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[156]: timeout = <undef>
1617570638.2417 DEBUG:<50> Net::SIP::Dispatcher::Eventloop::loop[172]: trigger timer(socketpool-timeout) 1617570638.23391 repeat=8
1617570638.2418 DEBUG:<99> Net::SIP::SocketPool::_timeout_sockets[310]: timeout sockets
1617570638.2418 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[176]: timer(socketpool-timeout) gets repeated at 1617570646
1617570638.2419 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[188]: timeout = 7.99236297607422
1617570638.2420 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[198]: BEFORE read=00010000 write=00001000
1617570646.2426 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[201]: AFTER  read=00000000 write=00000000 nfound=0
1617570646.2427 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::loop[156]: timeout = <undef>
1617570646.2428 DEBUG:<50> Net::SIP::Dispatcher::Eventloop::loop[172]: trigger timer(socketpool-timeout) 1617570646.23391 repeat=8
1617570646.2429 DEBUG:<99> Net::SIP::SocketPool::_timeout_sockets[310]: timeout sockets
1617570646.2429 DEBUG:<1> Net::SIP::SocketPool::_error[348]: connect timed out
1617570646.2430 DEBUG:<99> Net::SIP::Dispatcher::Eventloop::delFD[80]: Net::SIP::Dispatcher::Eventloop=HASH(0x5635aea06ad0) delete fn=4 sock=SRC_IP:SRC_PORT
1617570646.2431 DEBUG:<100> Net::SIP::Dispatcher::Eventloop::delFD[99]: maxfd=4
1617570646.2444 DEBUG:<100> Net::SIP::Simple::error[245]: 1617570646.2433 DEBUG: Net::SIP::Debug::stacktrace[193]: set error to Failed with error 110

This change contains also unit test which was able to trigger this issue and verifies that it does not happen anymore.

noxxi commented 3 years ago

Change looks better, but the error handling is currently only limited to TCP connect. I've extended it so that it should also cover TCP send and TLS connect

pali commented 3 years ago

Perfect, thank you!