Opened 8 years ago

Closed 8 years ago

#13008 closed defect (fixed)

BOSH - http Connection is not closed when connection : close header is received

Reported by: hsitas444 Owned by: deryni
Milestone: 2.7.10 Component: XMPP
Version: 2.7.5 Keywords: BOSH Connection Header
Cc:

Description

I am trying to connect to a bosh server that doesnot support http pipeling. The server sends connection header with value as 'close' which means that it doesnot support http pipeling and thus the client should terminate the tcp connection like browsers do.

I tried closing the tcp connection after sending the response at the server end. In this case pidgin disconnected saying connection: Connection error on 0xa8a5100 (reason: 0 description: Unable to establish a connection with the server)

I have attached pidgin logs for this case.

Attachments (2)

pidgin.logs (15.8 KB) - added by hsitas444 8 years ago.
Pidgin logs when server doesnot support pipeling
pidgin_verbose_debug.logs (19.7 KB) - added by hsitas444 8 years ago.
Uploaded pidgin logs with verbose set

Download all attachments as: .zip

Change History (21)

Changed 8 years ago by hsitas444

Pidgin logs when server doesnot support pipeling

comment:1 follow-up: Changed 8 years ago by darkrain42

Yes, we need to check for that header.

comment:2 Changed 8 years ago by darkrain42

  • Status changed from new to pending

The behavior when you're manually closing the connection on the server side looks broken to me (at the end, we give up because we opened multiple TCP connections and the server immediately closed them, or so it appears). A debug log with PURPLE_VERBOSE_DEBUG set would be helpful here, as well.

Changed 8 years ago by hsitas444

Uploaded pidgin logs with verbose set

comment:3 Changed 8 years ago by hsitas444

  • Status changed from pending to new

Attachment (pidgin_verbose_debug.logs) added by ticket reporter.

comment:5 Changed 8 years ago by hsitas444

I have uploaded pidgin logs with verbose set.

comment:6 Changed 8 years ago by hsitas444

Is there any way to let pidgin know that the server does not support pipelining. May be interms of bosh connection parameters.

Are you planning implementing the check for connection:close header?

comment:7 in reply to: ↑ 1 Changed 8 years ago by hsitas444

Replying to darkrain42:

Yes, we need to check for that header.

Are you planning implementing the check for connection:close header?

comment:8 Changed 8 years ago by darkrain42

libpurple assumes the server does not support pipelining if it closes the connection after sending a response. That said, looking at the verbose debug log, it unfortunately doesn't contain enough information to verify one way or the other what's going on when your server closes the connection, but it still looks like the server closes the connection the last few times immediately after establishment (before the client has a chance to send data).

Support for Connection: Close is a valid change that libpurple needs to make (patches quite welcome), which is why I said as much previously. If I find the time, it'll make it into the next release. If not, it will happen when I or someone finds the time.

comment:9 Changed 8 years ago by hsitas444

hi, any update on this issue?

comment:10 Changed 8 years ago by darkrain42@…

(In 8e517166b845534302353911425b9d8f7b2141d7):
jabber: Improved BOSH logging some. Refs #13008

comment:11 Changed 8 years ago by darkrain42@…

  • Milestone set to 2.7.10
  • Resolution set to fixed
  • Status changed from new to closed

(In 88aea2f701d6cff5efc151d40ef06257da67cf3d):
jabber: Handle the connection: close header. Closes #13008

We should also look for HTTP/1.0.

comment:12 Changed 8 years ago by hsitas444

I m using the fixed bosh file. When pidgin is not using pipelining, and waiting for a response on one http connection, it opens another http connection stays idle on the new http connection. Most http servers have idle connection timeout, so they disconnect the connection, when the server disconnects the connection pidgin says jabber: Could not find a HTTP connection'' and it disconnects.

Here is snippet of pidgin logs

(13:03:09) jabber: bosh: httpconn 0x8fbd700 re-connected
(13:03:09) jabber: BOSH 0x947e8e8->connections[0] = 0x959a858, state = 2, requests = 1
(13:03:09) jabber: BOSH 0x947e8e8->connections[1] = 0x8fbd700, state = 2, requests = 0
(13:03:09) jabber: BOSH session already exists. Trying to reuse it.
(13:03:19) jabber: BOSH server closed the connection (0x8fbd700)
(13:03:19) connection: Connection error on 0x9520d10 (reason: 0 description: Unable to establish a connection with the server)
(13:03:19) account: Disconnecting account testuser1@example.com/asdf (0x8dd7418)
(13:03:19) connection: Disconnecting connection 0x9520d10
(13:03:19) connection: Deactivating keepalive.
(13:03:19) jabber: BOSH 0x947e8e8->connections[0] = 0x959a858, state = 2, requests = 1
(13:03:19) jabber: BOSH 0x947e8e8->connections[1] = 0x8fbd700, state = 0, requests = 0
(13:03:19) jabber: Could not find a HTTP connection!
(13:03:19) jabber: BOSH (0x959a858): Sending request of 350 bytes.
(13:03:19) jabber: BOSH (0x959a858): wrote 350 bytes

comment:13 Changed 8 years ago by darkrain42

  • Resolution fixed deleted
  • Status changed from closed to new

What server is this, out of curiosity? It's very unfriendly to me.

comment:14 Changed 8 years ago by darkrain42@…

(In 50243dd37132d4ae636e94f587bf6a41617ccd0d):
jabber: Be friendlier to servers when we have nothing to say.

Don't try to reconnect immediately, but do so when we have something to send. Untested (I'll test it later), but I'm hoping hsitas444 will test it first. Refs #13008.

comment:15 Changed 8 years ago by hsitas444

Thanks for the quick update. But another problem has started, whenever pidgin has data to send it opens a new connection but the data is sent on connection[0].

Here is a snippet of pidgin logs

(16:07:54) jabber: BOSH 0x8c46b70->connections[0] = 0x85814e0, state = 0, requests = 0 (16:07:54) jabber: BOSH 0x8c46b70->connections[1] = 0x88b0780, state = 0, requests = 0 (16:07:54) jabber: bosh: Reconnecting httpconn (0, 0x85814e0) (16:07:54) dns: DNS query for 'w.x.y.z' queued (16:07:54) jabber: Unable to find a ready BOSH connection. Ignoring send of type 0x02. (16:07:54) dns: Successfully sent DNS request to child 27977 (16:07:54) dns: Got response for 'w.x.y.z' (16:07:54) dnsquery: IP resolved for w.x.y.z (16:07:54) proxy: Attempting connection to w.x.y.z (16:07:54) proxy: Connecting to w.x.y.z:port with no proxy (16:07:54) proxy: Connection in progress (16:07:55) proxy: Connecting to w.x.y.z:port. (16:07:55) proxy: Connected to w.x.y.z:port. (16:07:55) jabber: bosh: httpconn 0x85814e0 re-connected (16:07:55) jabber: BOSH 0x8c46b70->connections[0] = 0x85814e0, state = 2, requests = 0 (16:07:55) jabber: BOSH 0x8c46b70->connections[1] = 0x88b0780, state = 0, requests = 0 (16:07:55) jabber: BOSH session already exists. Trying to reuse it. (16:07:55) jabber: BOSH 0x8c46b70->connections[0] = 0x85814e0, state = 2, requests = 0 (16:07:55) jabber: BOSH 0x8c46b70->connections[1] = 0x88b0780, state = 0, requests = 0 (16:07:55) jabber: BOSH (0x85814e0): Sending request of 518 bytes. (16:07:55) jabber: BOSH (0x85814e0): wrote 518 bytes (16:08:00) pidgin-libnotify: closed_cb(), notification: 0x8764f60 (16:08:19) jabber: Sending (testuser1@…/asdf): <iq xmlns='jabber:client' type='get' id='purple10ed612b'><ping xmlns='urn:xmpp:ping'/></iq> (16:08:19) jabber: bosh: 0x8c46b70 has 91 bytes in the buffer. (16:08:20) jabber: BOSH 0x8c46b70->connections[0] = 0x85814e0, state = 2, requests = 1 (16:08:20) jabber: BOSH 0x8c46b70->connections[1] = 0x88b0780, state = 0, requests = 0 (16:08:20) jabber: bosh: Reconnecting httpconn (1, 0x88b0780) (16:08:20) dns: DNS query for 'w.x.y.z' queued (16:08:20) jabber: BOSH (0x85814e0): Sending request of 423 bytes. (16:08:20) jabber: BOSH (0x85814e0): wrote 423 bytes (16:08:20) dns: Wait for DNS child 27977 failed: No child processes (16:08:20) dns: Created new DNS child 28005, there are now 1 children. (16:08:20) dns: Successfully sent DNS request to child 28005 (16:08:20) dns: Got response for 'w.x.y.z' (16:08:20) dnsquery: IP resolved for w.x.y.z (16:08:20) proxy: Attempting connection to w.x.y.z (16:08:20) proxy: Connecting to w.x.y.z:port with no proxy (16:08:20) proxy: Connection in progress (16:08:21) proxy: Connecting to w.x.y.z:port. (16:08:21) proxy: Connected to w.x.y.z:port. (16:08:21) jabber: bosh: httpconn 0x88b0780 re-connected (16:08:21) jabber: BOSH 0x8c46b70->connections[0] = 0x85814e0, state = 2, requests = 2 (16:08:21) jabber: BOSH 0x8c46b70->connections[1] = 0x88b0780, state = 2, requests = 0 (16:08:21) jabber: BOSH session already exists. Trying to reuse it. (16:08:29) jabber: BOSH server closed the connection (0x88b0780) (16:08:45) jabber: BOSH 0x8c46b70->connections[0] = 0x85814e0, state = 2, requests = 2 (16:08:45) jabber: BOSH 0x8c46b70->connections[1] = 0x88b0780, state = 0, requests = 0 (16:08:45) jabber: bosh: Reconnecting httpconn (1, 0x88b0780) (16:08:45) dns: DNS query for 'w.x.y.z' queued (16:08:45) jabber: BOSH (0x85814e0): Sending request of 332 bytes. (16:08:45) jabber: BOSH (0x85814e0): wrote 332 bytes (16:08:45) dns: Wait for DNS child 28005 failed: No child processes (16:08:45) dns: Created new DNS child 28008, there are now 1 children. (16:08:45) dns: Successfully sent DNS request to child 28008 (16:08:45) dns: Got response for 'w.x.y.z' (16:08:45) dnsquery: IP resolved for w.x.y.z (16:08:45) proxy: Attempting connection to w.x.y.z (16:08:45) proxy: Connecting to w.x.y.z:port with no proxy (16:08:45) proxy: Connection in progress (16:08:46) proxy: Connecting to w.x.y.z:port. (16:08:46) proxy: Connected to w.x.y.z:port. (16:08:46) jabber: bosh: httpconn 0x88b0780 re-connected (16:08:46) jabber: BOSH 0x8c46b70->connections[0] = 0x85814e0, state = 2, requests = 3 (16:08:46) jabber: BOSH 0x8c46b70->connections[1] = 0x88b0780, state = 2, requests = 0 (16:08:46) jabber: BOSH session already exists. Trying to reuse it. (16:08:54) jabber: BOSH server closed the connection (0x88b0780)

comment:16 Changed 8 years ago by hsitas444

Sorry about the previous indentation.

(16:07:54) jabber: BOSH 0x8c46b70->connections[0] = 0x85814e0, state = 0, requests = 0
(16:07:54) jabber: BOSH 0x8c46b70->connections[1] = 0x88b0780, state = 0, requests = 0
(16:07:54) jabber: bosh: Reconnecting httpconn (0, 0x85814e0)
(16:07:54) dns: DNS query for 'w.x.y.z' queued
(16:07:54) jabber: Unable to find a ready BOSH connection. Ignoring send of type 0x02.
(16:07:54) dns: Successfully sent DNS request to child 27977
(16:07:54) dns: Got response for 'w.x.y.z'
(16:07:54) dnsquery: IP resolved for w.x.y.z
(16:07:54) proxy: Attempting connection to w.x.y.z
(16:07:54) proxy: Connecting to w.x.y.z:port with no proxy
(16:07:54) proxy: Connection in progress
(16:07:55) proxy: Connecting to w.x.y.z:port.
(16:07:55) proxy: Connected to w.x.y.z:port.
(16:07:55) jabber: bosh: httpconn 0x85814e0 re-connected
(16:07:55) jabber: BOSH 0x8c46b70->connections[0] = 0x85814e0, state = 2, requests = 0
(16:07:55) jabber: BOSH 0x8c46b70->connections[1] = 0x88b0780, state = 0, requests = 0
(16:07:55) jabber: BOSH session already exists. Trying to reuse it.
(16:07:55) jabber: BOSH 0x8c46b70->connections[0] = 0x85814e0, state = 2, requests = 0
(16:07:55) jabber: BOSH 0x8c46b70->connections[1] = 0x88b0780, state = 0, requests = 0
(16:07:55) jabber: BOSH (0x85814e0): Sending request of 518 bytes.
(16:07:55) jabber: BOSH (0x85814e0): wrote 518 bytes
(16:08:00) pidgin-libnotify: closed_cb(), notification: 0x8764f60
(16:08:19) jabber: Sending (testuser1@example.com/asdf): <iq xmlns='jabber:client' type='get' id='purple10ed612b'><ping xmlns='urn:xmpp:ping'/></iq>
(16:08:19) jabber: bosh: 0x8c46b70 has 91 bytes in the buffer.
(16:08:20) jabber: BOSH 0x8c46b70->connections[0] = 0x85814e0, state = 2, requests = 1
(16:08:20) jabber: BOSH 0x8c46b70->connections[1] = 0x88b0780, state = 0, requests = 0
(16:08:20) jabber: bosh: Reconnecting httpconn (1, 0x88b0780)
(16:08:20) dns: DNS query for 'w.x.y.z' queued
(16:08:20) jabber: BOSH (0x85814e0): Sending request of 423 bytes.
(16:08:20) jabber: BOSH (0x85814e0): wrote 423 bytes
(16:08:20) dns: Wait for DNS child 27977 failed: No child processes
(16:08:20) dns: Created new DNS child 28005, there are now 1 children.
(16:08:20) dns: Successfully sent DNS request to child 28005
(16:08:20) dns: Got response for 'w.x.y.z'
(16:08:20) dnsquery: IP resolved for w.x.y.z
(16:08:20) proxy: Attempting connection to w.x.y.z
(16:08:20) proxy: Connecting to w.x.y.z:port with no proxy
(16:08:20) proxy: Connection in progress
(16:08:21) proxy: Connecting to w.x.y.z:port.
(16:08:21) proxy: Connected to w.x.y.z:port.
(16:08:21) jabber: bosh: httpconn 0x88b0780 re-connected
(16:08:21) jabber: BOSH 0x8c46b70->connections[0] = 0x85814e0, state = 2, requests = 2
(16:08:21) jabber: BOSH 0x8c46b70->connections[1] = 0x88b0780, state = 2, requests = 0
(16:08:21) jabber: BOSH session already exists. Trying to reuse it.
(16:08:29) jabber: BOSH server closed the connection (0x88b0780)
(16:08:45) jabber: BOSH 0x8c46b70->connections[0] = 0x85814e0, state = 2, requests = 2
(16:08:45) jabber: BOSH 0x8c46b70->connections[1] = 0x88b0780, state = 0, requests = 0
(16:08:45) jabber: bosh: Reconnecting httpconn (1, 0x88b0780)
(16:08:45) dns: DNS query for 'w.x.y.z' queued
(16:08:45) jabber: BOSH (0x85814e0): Sending request of 332 bytes.
(16:08:45) jabber: BOSH (0x85814e0): wrote 332 bytes
(16:08:45) dns: Wait for DNS child 28005 failed: No child processes
(16:08:45) dns: Created new DNS child 28008, there are now 1 children.
(16:08:45) dns: Successfully sent DNS request to child 28008
(16:08:45) dns: Got response for 'w.x.y.z'
(16:08:45) dnsquery: IP resolved for w.x.y.z
(16:08:45) proxy: Attempting connection to w.x.y.z
(16:08:45) proxy: Connecting to w.x.y.z:port with no proxy
(16:08:45) proxy: Connection in progress
(16:08:46) proxy: Connecting to w.x.y.z:port.
(16:08:46) proxy: Connected to w.x.y.z:port.
(16:08:46) jabber: bosh: httpconn 0x88b0780 re-connected
(16:08:46) jabber: BOSH 0x8c46b70->connections[0] = 0x85814e0, state = 2, requests = 3
(16:08:46) jabber: BOSH 0x8c46b70->connections[1] = 0x88b0780, state = 2, requests = 0
(16:08:46) jabber: BOSH session already exists. Trying to reuse it.
(16:08:54) jabber: BOSH server closed the connection (0x88b0780)

comment:17 Changed 8 years ago by hsitas444

hi, any updates on this issue?

comment:18 Changed 8 years ago by darkrain42@…

(In 36816746a73da13a5358b6c78bb82d1d40925555):
jabber: bosh: Hopefully a final corrective fix. Refs #13008

comment:19 Changed 8 years ago by hsitas444

thanks for the fix.:)

comment:20 Changed 8 years ago by darkrain42

  • Milestone changed from 2.7.11 to 2.7.10
  • Resolution set to fixed
  • Status changed from new to closed

I think this was fixed

Note: See TracTickets for help on using tickets.
All information, including names and email addresses, entered onto this website or sent to mailing lists affiliated with this website will be public. Do not post confidential information, especially passwords!