Direct connection freeze

[amroth]

While checking a log file I noticed a large chunk of it was made from the same two messages. There was an error regarding a certain quantity of bytes written to a DC.

Then it went on a freeze until the timeout came and closed the DC.

Here's the log.

kmess: DirectConnectionPool::slotConnectionEstablished() - Direct connection established.
kmess: DirectConnectionPool::slotConnectionEstablished() - Connected to peer IP:PORT
kmess: ApplicationList: Direct connection with 'contact@kmess.org' established.
kmess: P2PApplication::slotConnectionEstablished() - Direct connection established.
kmess: P2PApplication::slotConnectionEstablished() - Waiting for contact to send connection handshake...
kmess: MsnDirectConnection: 4 bytes read, next block size is 4, 4 bytes yet to be read.
kmess: MsnDirectConnection::slotDataReceived: 4 bytes read, 0 bytes remaining.
kmess: MsnDirectConnection::slotDataReceived: received preamble packet, ignoring.
kmess: MsnDirectConnection: 4 bytes read, next block size is 48, 4 bytes yet to be read.
kmess: MsnDirectConnection::slotDataReceived: 48 bytes read, 0 bytes remaining.
kmess: MsnDirectConnection: Emitting message received signal.
kmess: ApplicationList: Received data message from the direct connection link (flags=0x100).
kmess: ApplicationList: Demultiplexing P2P message    (Nonce {3BEDB1D6-B351-933E-3BE0-113999A69160} == {3BEDB1D6-B351-933E-3BE0-113999A69160} ?)
kmess: P2PApplication::gotMessage() - Message size=0 total=0 offset=0 contact=contact@kmess.org
kmess: P2PApplication::getUnAckedMessage() - Testing if P2P ACK matches    (UniqueID 16239236 == 2470359889 ?) or (UniqueID 16239236 == 1005433302 ?) or (MessageID 11899557 == 1005433302 ?)
kmess: P2PApplication::gotDirectConnectionHandshake() - Got a direct connection handshake message.
kmess: DirectConnectionPool::slotConnectionAuthorized() - A direct connection was authorized.
kmess: ApplicationList: Direct connection with 'contact@kmess.org' authorized.
kmess: P2PApplication::slotConnectionAuthorized() - Direct connection authorized, starting transfer.
kmess: P2PApplication::initiateTransfer() - Signalling implementation class to start the file transfer.
kmess: P2PApplication::sendData() - Begin of data transfer
kmess: ApplicationList::registerDataSendingApplication() - adding application to the list of active outgoing transfers.
kmess: WARNING: ApplicationList::registerDataSendingApplication() - no write handler connected yet.
kmess: P2PApplication::gotDirectConnectionHandshake() - Contact sent correct nonce, sending direct connection handshake ACK.
kmess: P2PApplication::sendDirectConnectionHandshake() - Sending direct connection handshake (nonce={3BEDB1D6-B351-933E-3BE0-113999A69160}).
kmess: P2PApplication::sendDirectConnectionHandshake() - copied nonce '{3BEDB1D6-B351-933E-3BE0-113999A69160}' to p2p message header as 'D6B1ED3B-51B3-3E93-3BE0-113999A69160'.
kmess: MsnDirectConnection: sending message block (size=48, handle=contact@kmess.org)
kmess: P2PApplication::sendDirectConnectionHandshake() - Waiting for direct connection handshake response...
kmess: ApplicationList::slotConnectionReadyWrite() - The direct connection is ready to send more data, notifying applications.
kmess: P2PApplication::sendNextDataParts() - Sending data: offset=0 buffer=371
kmess: MsnDirectConnection: sending message block (size=419, handle=contact@kmess.org)
kmess: P2PApplication::sendP2PMessage() - Storing message fields in queue for ACK response.
kmess: P2PApplication::sendP2PMessage() - Message transmitted (SID=5980896 MID=11899559 UID=1669532 flags=0x20 size=371 type=5)
kmess: Application::showTransferProgress: Transferred 371 bytes.
kmess: WARNING: P2PApplication::sendNextDataParts() - data source is at the end, but offset byte count is not!
kmess: ApplicationList::unregisterDataSendingApplication() - removing application from the list of active outgoing transfers.
kmess: ApplicationList::slotConnectionReadyWrite() - The direct connection is ready to send more data, notifying applications.
kmess: WARNING: 'dataSource_' should not be null in void P2PApplication::sendNextDataParts(), /www/development/kmess/kmess/network/applications/p2papplication.cpp (2939)!
kmess: ApplicationList::slotConnectionReadyWrite() - The direct connection is ready to send more data, notifying applications.
kmess: WARNING: 'dataSource_' should not be null in void P2PApplication::sendNextDataParts(), /www/development/kmess/kmess/network/applications/p2papplication.cpp (2939)!
kmess: ApplicationList::slotConnectionReadyWrite() - The direct connection is ready to send more data, notifying applications.
kmess: WARNING: 'dataSource_' should not be null in void P2PApplication::sendNextDataParts(), /www/development/kmess/kmess/network/applications/p2papplication.cpp (2939)!
kmess: ApplicationList::slotConnectionReadyWrite() - The direct connection is ready to send more data, notifying applications.
kmess: WARNING: 'dataSource_' should not be null in void P2PApplication::sendNextDataParts(), /www/development/kmess/kmess/network/applications/p2papplication.cpp (2939)!
......
kmess: ApplicationList::slotConnectionReadyWrite() - The direct connection is ready to send more data, notifying applications.
kmess: WARNING: 'dataSource_' should not be null in void P2PApplication::sendNextDataParts(), /www/development/kmess/kmess/network/applications/p2papplication.cpp (2939)!
kmess: ApplicationList::slotConnectionReadyWrite() - The direct connection is ready to send more data, notifying applications.
kmess: WARNING: 'dataSource_' should not be null in void P2PApplication::sendNextDataParts(), /www/development/kmess/kmess/network/applications/p2papplication.cpp (2939)!
kmess: P2PApplication::slotCleanup() - timeout fired, cleaning up (waitingState=14).
kmess: MsnDirectConnection: sending message block (size=48, handle=contact@kmess.org)
kmess: P2PApplication::sendP2PMessage() - Message transmitted (SID=5980896 MID=11899561 UID=5637112 flags=0x4 size=0 type=0)
kmess: WARNING: P2PApplication::slotCleanup() - Timeout waiting for DC handshake response (contact=contact@kmess.org).

[amroth]

There must be a couple issues in the DC code right now, i've got another freeze, this one had cost me a 390 megabyte log, before I killed the process :D

kmess: P2PApplication::sendDirectConnectionHandshake() - Waiting for direct connection handshake response...
kmess: MsnDirectConnection: 4 bytes read, next block size is 1250, 4 bytes yet to be read.
kmess: MsnDirectConnection::slotDataReceived: 1250 bytes read, 0 bytes remaining.
kmess: MsnDirectConnection: Emitting message received signal.
kmess: ApplicationList: Received data message from the direct connection link (flags=0x1000030).
kmess: ApplicationList: Parsing P2P: SID=14172844 MID=1847753 AckID=2655144 ACKUID=0 flags=0x1000030 size=1202 no.sessions=1
kmess: ApplicationList: Demultiplexing P2P message    (SessionID 14172844 == 14172844 ?)
kmess: P2PApplication::gotMessage() - Message size=1202 total=17841981 offset=0 contact=contact@kmess.org
kmess: P2PApplication::gotDataFragment() - Received file data, calling gotData().
kmess: TransferEntry::updateProgress() - transfer is at 0 percent.
kmess: FileTransferP2P::gotData() - Data part received, saving data to file.
kmess: MsnDirectConnection: 4 bytes read, next block size is 1250, 4 bytes yet to be read.
kmess: WARNING: DirectConnectionBase::readBlock() - only 160 of 1250 bytes could be read!
kmess: MsnDirectConnection::slotDataReceived: 160 bytes read, 1090 bytes remaining.
QGArray::at: Absolute index -584684150 out of range
QGArray::at: Absolute index -584684149 out of range
QGArray::at: Absolute index -584684148 out of range
QGArray::at: Absolute index -584684147 out of range
QGArray::at: Absolute index -584684146 out of range
QGArray::at: Absolute index -584684145 out of range
QGArray::at: Absolute index -584684144 out of range
QGArray::at: Absolute index -584684143 out of range

[amroth]

Another one, very similar but with longer previous problems.

kmess: PictureTransferP2P - userStarted2_ContactAccepts
kmess: P2PApplication::gotSlpOk() - Waiting for contact to send some prepare message...
kmess: MsnDirectConnection: 4 bytes read, next block size is 52, 4 bytes yet to be read.
kmess: MsnDirectConnection::slotDataReceived: 52 bytes read, 0 bytes remaining.
kmess: MsnDirectConnection: Emitting message received signal.
kmess: ApplicationList: Received data message from the direct connection link (flags=0x0).
kmess: ApplicationList: Parsing P2P: SID=14833596 MID=235026 AckID=25285453 ACKUID=0 flags=0x0 size=4 no.sessions=1
kmess: ApplicationList: Demultiplexing P2P message    (SessionID 14833596 == 14833596 ?)
kmess: P2PApplication::gotMessage() - Message size=4 total=4 offset=0 contact=contact@kmess.org
kmess: P2PApplication::gotDataPreparation() - Got the data preparation message
kmess: P2PApplication::initiateTransfer() - Signalling implementation class to start the file transfer.
kmess: PictureTransferP2P - userStarted3_UserPrepares
kmess: P2PApplication::gotDataPreparation() - Data preparation successful, sending ACK
kmess: P2PApplication::sendP2PAck() - Sending P2P ACK
kmess: MsnDirectConnection: sending message block (size=48, handle=contact@kmess.org)
kmess: P2PApplication::sendP2PAck() - ACK Transmitted (flags=0x2).
kmess: P2PApplication::gotDataPreparation() - Waiting for file data to arrive...
kmess: MsnDirectConnection: 4 bytes read, next block size is 1400, 4 bytes yet to be read.
kmess: WARNING: DirectConnectionBase::readBlock() - only 884 of 1400 bytes could be read!
kmess: MsnDirectConnection::slotDataReceived: 884 bytes read, 516 bytes remaining.
kmess: MsnDirectConnection::slotDataReceived: 516 bytes read, 0 bytes remaining.
kmess: MsnDirectConnection: Emitting message received signal.
kmess: ApplicationList: Received data message from the direct connection link (flags=0x20).
kmess: ApplicationList: Parsing P2P: SID=14833596 MID=235027 AckID=25285453 ACKUID=0 flags=0x20 size=1352 no.sessions=1
kmess: ApplicationList: Demultiplexing P2P message    (SessionID 14833596 == 14833596 ?)
kmess: P2PApplication::gotMessage() - Message size=1352 total=4574 offset=0 contact=contact@kmess.org
kmess: P2PApplication::gotDataFragment() - Received file data, calling gotData().
kmess: Application::showTransferProgress: Transferred 1352 bytes.
kmess: MsnDirectConnection: 4 bytes read, next block size is 1400, 4 bytes yet to be read.
kmess: WARNING: DirectConnectionBase::readBlock() - only 910 of 1400 bytes could be read!
kmess: MsnDirectConnection::slotDataReceived: 910 bytes read, 490 bytes remaining.
kmess: MsnDirectConnection::slotDataReceived: 490 bytes read, 0 bytes remaining.
kmess: MsnDirectConnection: Emitting message received signal.
kmess: ApplicationList: Received data message from the direct connection link (flags=0x20).
kmess: ApplicationList: Parsing P2P: SID=14833596 MID=235027 AckID=25285453 ACKUID=0 flags=0x20 size=1352 no.sessions=1
kmess: ApplicationList: Demultiplexing P2P message    (SessionID 14833596 == 14833596 ?)
kmess: P2PApplication::gotMessage() - Message size=1352 total=4574 offset=1352 contact=contact@kmess.org
kmess: P2PApplication::gotDataFragment() - Received file data, calling gotData().
kmess: Application::showTransferProgress: Transferred 2704 bytes.
kmess: MsnDirectConnection: 4 bytes read, next block size is 1400, 4 bytes yet to be read.
kmess: WARNING: DirectConnectionBase::readBlock() - only 936 of 1400 bytes could be read!
kmess: MsnDirectConnection::slotDataReceived: 936 bytes read, 464 bytes remaining.
QGArray::at: Absolute index -407350724 out of range
QGArray::at: Absolute index -407350723 out of range
QGArray::at: Absolute index -407350722 out of range

[diederik]

Which client were you exchanging files with? An older KMess client?

[amroth]

Honestly, I don't know about the second kind of freeze, the QGArray::at one. It was a background picture exchange. The first freeze happened at least 3-4 times with almost latest kmess-SVN, and with WLM.

[diederik]

Observations of the first log file

kmess: ApplicationList: Direct connection with 'contact@kmess.org' authorized.
kmess: P2PApplication::slotConnectionAuthorized() - Direct connection authorized, starting transfer.
kmess: P2PApplication::initiateTransfer() - Signalling implementation class to start the file transfer.

So the connection is authorized correctly and the transfer may start

kmess: P2PApplication::sendData() - Begin of data transfer
kmess: ApplicationList::registerDataSendingApplication() - adding application to the list of active outgoing transfers.
kmess: WARNING: ApplicationList::registerDataSendingApplication() - no write handler connected yet.

It seams the write handler is not disconnected, even though all applications are removed. Found a possible cause for this in ApplicationList::slotTerminateApplication(). Changing that to unregister the application correctly.

kmess: WARNING: P2PApplication::sendNextDataParts() - data source is at the end, but offset byte count is not!
kmess: ApplicationList::unregisterDataSendingApplication() - removing application from the list of active outgoing transfers.

Not sure what went wrong there, but the first action triggers the unregisteration and resets the dataSource_.

kmess: ApplicationList::slotConnectionReadyWrite() - The direct connection is ready to send more data, notifying applications.
kmess: WARNING: 'dataSource_' should not be null in void P2PApplication::sendNextDataParts(), /www/development/kmess/kmess/network/applications/p2papplication.cpp (2939)!

Even though the app unregistered, it seams to be getting more requests. This is the real weird part. To fix some freezes here, I've added an unregisterDataSendingApplication() call after that KMESS_NULL() check. Apps which can't send data shouldn't be called again.

[amroth]

This seems to be fixed. Yay! Fix for the commit was r2198.