| Summary: | ASTERISK-21016: One-way audio with JABBER correlates with 'res_xmpp.c: JABBER: socket read error' in debug | ||||
| Reporter: | Sam Youtsey (syoutsey) | Labels: | |||
| Date Opened: | 2013-01-31 10:37:22.000-0600 | Date Closed: | 2013-02-05 19:04:12.000-0600 | ||
| Priority: | Major | Regression? | |||
| Status: | Closed/Complete | Components: | Channels/chan_motif | ||
| Versions: | 11.2.1 | Frequency of Occurrence | Occasional | ||
| Related Issues: |
| ||||
| Environment: | Ubuntu 12.04 | Attachments: | |||
| Description: | The affected system is using Google Voice for outgoing calls. The Asterisk messages log will show a line of 'WARNING[23263] res_xmpp.c: JABBER: socket read error'. At this point, only 1-way audio is possible. A restart of a Asterisk is required to re-enable full audio support. Unfortunately, I haven't found a way to make to make this reproducible. I've attached the logs below and included a Pastebin link. The line in question occurs towards the end of the file.
{code} [Jan 31 07:52:38] DEBUG[23282] chan_sip.c: Stopping retransmission on '047074022b8d12eb69a223591b79d5fc@192.168.187.7:5060' of Request 102: Match Found [Jan 31 07:52:38] DEBUG[23282] chan_sip.c: Destroying SIP dialog 047074022b8d12eb69a223591b79d5fc@192.168.187.7:5060 [Jan 31 07:53:10] DEBUG[23282] chan_sip.c: Auto destroying SIP dialog 'fc7c19dfc5482359' [Jan 31 07:53:10] DEBUG[23282] chan_sip.c: Destroying SIP dialog fc7c19dfc5482359 [Jan 31 07:53:18] DEBUG[23263] res_xmpp.c: XML parsing successful [Jan 31 07:53:32] DEBUG[23282] acl.c: For destination '192.168.187.45', our source address is '192.168.187.7'. [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.187.7:5060 [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Allocating new SIP dialog for 49808d59aad3d5e0 - REGISTER (No RTP) [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.187.45:5060 [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Store REGISTER's Contact header for call routing. [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.187.45:5060 [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Allocating new SIP dialog for 0b74eba33ad733936cea878651eeb3dd@127.0.1.1:5060 - NOTIFY (No RTP) [Jan 31 07:53:32] DEBUG[23282] acl.c: For destination '192.168.187.45', our source address is '192.168.187.7'. [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.187.7:5060 [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Initializing initreq for method NOTIFY - callid 1469de100f60510d7dc7779d2eed7287@192.168.187.7:5060 [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.187.45:5060 [Jan 31 07:53:32] DEBUG[23257] chan_sip.c: Checking device state for peer shannon-phone [Jan 31 07:53:32] DEBUG[23257] devicestate.c: Changing state for SIP/shannon-phone - state 1 (Not in use) [Jan 31 07:53:32] DEBUG[23257] devicestate.c: device 'SIP/shannon-phone' state '1' [Jan 31 07:53:32] DEBUG[23295] app_queue.c: Device 'SIP/shannon-phone' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Stopping retransmission on '1469de100f60510d7dc7779d2eed7287@192.168.187.7:5060' of Request 102: Match Found [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Destroying SIP dialog 1469de100f60510d7dc7779d2eed7287@192.168.187.7:5060 [Jan 31 07:53:32] DEBUG[23282] acl.c: For destination '192.168.187.47', our source address is '192.168.187.7'. [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.187.7:5060 [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Allocating new SIP dialog for 910f621a396a2512 - REGISTER (No RTP) [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.187.47:5060 [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Store REGISTER's Contact header for call routing. [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.187.47:5060 [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Allocating new SIP dialog for 274aafb0516ace5c108a64df45b9bda3@127.0.1.1:5060 - NOTIFY (No RTP) [Jan 31 07:53:32] DEBUG[23282] acl.c: For destination '192.168.187.47', our source address is '192.168.187.7'. [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.187.7:5060 [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Initializing initreq for method NOTIFY - callid 6a6b142b5ed1f4bd305eeaff6063a4c2@192.168.187.7:5060 [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.187.47:5060 [Jan 31 07:53:32] DEBUG[23257] chan_sip.c: Checking device state for peer derek-phone [Jan 31 07:53:32] DEBUG[23257] devicestate.c: Changing state for SIP/derek-phone - state 1 (Not in use) [Jan 31 07:53:32] DEBUG[23257] devicestate.c: device 'SIP/derek-phone' state '1' [Jan 31 07:53:32] DEBUG[23295] app_queue.c: Device 'SIP/derek-phone' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Stopping retransmission on '6a6b142b5ed1f4bd305eeaff6063a4c2@192.168.187.7:5060' of Request 102: Match Found [Jan 31 07:53:32] DEBUG[23282] chan_sip.c: Destroying SIP dialog 6a6b142b5ed1f4bd305eeaff6063a4c2@192.168.187.7:5060 [Jan 31 07:54:04] DEBUG[23282] chan_sip.c: Auto destroying SIP dialog '49808d59aad3d5e0' [Jan 31 07:54:04] DEBUG[23282] chan_sip.c: Destroying SIP dialog 49808d59aad3d5e0 [Jan 31 07:54:04] DEBUG[23282] chan_sip.c: Auto destroying SIP dialog '910f621a396a2512' [Jan 31 07:54:04] DEBUG[23282] chan_sip.c: Destroying SIP dialog 910f621a396a2512 [Jan 31 07:54:31] DEBUG[23282] acl.c: For destination '192.168.187.86', our source address is '192.168.187.7'. [Jan 31 07:54:31] DEBUG[23282] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.187.7:5060 [Jan 31 07:54:31] DEBUG[23282] chan_sip.c: Allocating new SIP dialog for 62eacd0ea9e9d98a - REGISTER (No RTP) [Jan 31 07:54:31] DEBUG[23282] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.187.86:5060 [Jan 31 07:54:31] DEBUG[23282] chan_sip.c: Store REGISTER's Contact header for call routing. [Jan 31 07:54:31] DEBUG[23282] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.187.86:5060 [Jan 31 07:54:31] DEBUG[23282] chan_sip.c: Allocating new SIP dialog for 73e0981b4ad0661f6eed4a7a2342a711@127.0.1.1:5060 - NOTIFY (No RTP) [Jan 31 07:54:31] DEBUG[23282] acl.c: For destination '192.168.187.86', our source address is '192.168.187.7'. [Jan 31 07:54:31] DEBUG[23282] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.187.7:5060 [Jan 31 07:54:31] DEBUG[23282] chan_sip.c: Initializing initreq for method NOTIFY - callid 568af2f0132d564b337d9fd7198f4792@192.168.187.7:5060 [Jan 31 07:54:31] DEBUG[23282] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.187.86:5060 [Jan 31 07:54:31] DEBUG[23257] chan_sip.c: Checking device state for peer sam-phone [Jan 31 07:54:31] DEBUG[23257] devicestate.c: Changing state for SIP/sam-phone - state 1 (Not in use) [Jan 31 07:54:31] DEBUG[23257] devicestate.c: device 'SIP/sam-phone' state '1' [Jan 31 07:54:31] DEBUG[23295] app_queue.c: Device 'SIP/sam-phone' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Stopping retransmission on '568af2f0132d564b337d9fd7198f4792@192.168.187.7:5060' of Request 102: Match Found [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Destroying SIP dialog 568af2f0132d564b337d9fd7198f4792@192.168.187.7:5060 [Jan 31 07:54:32] DEBUG[23282] acl.c: For destination '192.168.187.58', our source address is '192.168.187.7'. [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.187.7:5060 [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Allocating new SIP dialog for a653fc7521496815 - REGISTER (No RTP) [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.187.58:5060 [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Store REGISTER's Contact header for call routing. [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.187.58:5060 [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Allocating new SIP dialog for 2b7ac1214b1d121a73c7628671a270f6@127.0.1.1:5060 - NOTIFY (No RTP) [Jan 31 07:54:32] DEBUG[23282] acl.c: For destination '192.168.187.58', our source address is '192.168.187.7'. [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.187.7:5060 [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Initializing initreq for method NOTIFY - callid 69f267a7131fb0df358f555748ebcfd6@192.168.187.7:5060 [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.187.58:5060 [Jan 31 07:54:32] DEBUG[23257] chan_sip.c: Checking device state for peer amy-phone [Jan 31 07:54:32] DEBUG[23257] devicestate.c: Changing state for SIP/amy-phone - state 1 (Not in use) [Jan 31 07:54:32] DEBUG[23257] devicestate.c: device 'SIP/amy-phone' state '1' [Jan 31 07:54:32] DEBUG[23295] app_queue.c: Device 'SIP/amy-phone' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 31 07:54:32] DEBUG[23282] acl.c: For destination '192.168.187.50', our source address is '192.168.187.7'. [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.187.7:5060 [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Allocating new SIP dialog for a9fc22d3a6a959e8 - REGISTER (No RTP) [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 192.168.187.50:5060 [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Stopping retransmission on '69f267a7131fb0df358f555748ebcfd6@192.168.187.7:5060' of Request 102: Match Found [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Destroying SIP dialog 69f267a7131fb0df358f555748ebcfd6@192.168.187.7:5060 [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Store REGISTER's Contact header for call routing. [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 192.168.187.50:5060 [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Allocating new SIP dialog for 432edf9f1b8be49b61be4d0e2f631ede@127.0.1.1:5060 - NOTIFY (No RTP) [Jan 31 07:54:32] DEBUG[23282] acl.c: For destination '192.168.187.50', our source address is '192.168.187.7'. [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.187.7:5060 [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Initializing initreq for method NOTIFY - callid 041aed7a1982ca59044c6f583c7f6d22@192.168.187.7:5060 [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.187.50:5060 [Jan 31 07:54:32] DEBUG[23257] chan_sip.c: Checking device state for peer joe-phone [Jan 31 07:54:32] DEBUG[23257] devicestate.c: Changing state for SIP/joe-phone - state 1 (Not in use) [Jan 31 07:54:32] DEBUG[23257] devicestate.c: device 'SIP/joe-phone' state '1' [Jan 31 07:54:32] DEBUG[23295] app_queue.c: Device 'SIP/joe-phone' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Stopping retransmission on '041aed7a1982ca59044c6f583c7f6d22@192.168.187.7:5060' of Request 102: Match Found [Jan 31 07:54:32] DEBUG[23282] chan_sip.c: Destroying SIP dialog 041aed7a1982ca59044c6f583c7f6d22@192.168.187.7:5060 [Jan 31 07:54:47] WARNING[23263] res_xmpp.c: JABBER: socket read error [Jan 31 07:54:47] DEBUG[23263] res_xmpp.c: Connecting client 'google' [Jan 31 07:54:47] DEBUG[23263] res_xmpp.c: XML parsing successful [Jan 31 07:54:47] DEBUG[23263] res_xmpp.c: TLS connection for client 'google' started with server [Jan 31 07:54:47] DEBUG[23263] res_xmpp.c: XML parsing successful [Jan 31 07:54:47] DEBUG[23263] res_xmpp.c: XML parsing successful {code} http://pastebin.com/A77tRYGu | ||||
| Comments: | By: Rusty Newton (rnewton) 2013-02-05 19:04:12.981-0600 Closing out, as this is a duplicate of ASTERISK-20916. The reporter can see that issue for the fix. | ||||