Skip to content
This repository has been archived by the owner on Oct 17, 2019. It is now read-only.

Only single message could be delivered #413

Open
unclechu opened this issue Aug 21, 2018 · 16 comments
Open

Only single message could be delivered #413

unclechu opened this issue Aug 21, 2018 · 16 comments
Labels
bug

Comments

@unclechu
Copy link

System:

  • Nheko version: 0.5.3
  • Installation method:
λ dnf info nheko 2>/dev/null
Last metadata expiration check: 0:00:15 ago on Wed 22 Aug 2018 02:27:59 AM MSK.
Installed Packages
Name         : nheko
Version      : 0.5.3
Release      : 2.fc28
Arch         : x86_64
Size         : 8.0 M
Source       : nheko-0.5.3-2.fc28.src.rpm
Repo         : @System
From repo    : updates
Summary      : Desktop client for the Matrix protocol
URL          : https://github.com/mujx/nheko
License      : GPLv3+ and ASL 2.0 and CC-BY
Description  : The motivation behind the project is to provide a native desktop app
             : for Matrix that feels more like a mainstream chat app.
  • Operating System: Fedora Workstation 28
  • Desktop Environment: i3wm

Actual behavior

Second message doesn't even get a sending icon. After that chat is dead, I also won't receive any next message.
out

Expected behavior

Second message is delivered

Steps to reproduce

  1. Send one message;
  2. Then try to send another.

Logs

[2018-08-22 02:17:00.846] [db] [error] saving sync response: mdb_put: MDB_MAP_FULL: Environment mapsize limit reached
@mujx mujx added the bug label Aug 22, 2018
@mujx
Copy link
Owner

mujx commented Aug 22, 2018

Thanks for the very detailed bug report!

This seems like the lmdb is full and it can't receive the next sync response.

It will need a way to automatically remove old saved messages which I assume occupy most space.

@unclechu
Copy link
Author

@mujx 256MiB is the limit?

λ pwd && ls | xargs -i du -h {}
/home/uc/.cache/nheko/nheko/40756e636c656368753a6d61747269782e6f7267
256M	data.mdb
4.0K	lock.mdb

I'm not surprised since I have more than 150 rooms.

@mujx
Copy link
Owner

mujx commented Aug 22, 2018

@unclechu Yes, that's the limit as defined below

nheko/src/Cache.cpp

Lines 135 to 138 in 199a4ea

env_ = lmdb::env::create();
env_.set_mapsize(256UL * 1024UL * 1024UL); /* 256 MB */
env_.set_max_dbs(1024UL);

@mujx mujx closed this as completed in 345dca3 Aug 25, 2018
@unclechu
Copy link
Author

@mujx Please initiate fresh nightly release so I could test it.

@unclechu
Copy link
Author

@mujx On current nightly release of 9f43ff8 I still have this issue, but error message is different:

[2018-08-26 16:51:59.772] [db] [error] lmdb is full: mdb_put: MDB_MAP_FULL: Environment mapsize limit reached
[2018-08-26 16:51:59.774] [db] [info] [%SOME_INTERNAL_ROOM_ID%] message count: 174
[2018-08-26 16:51:59.776] [db] [error] failed to delete old messages: mdb_cursor_del: MDB_MAP_FULL: Environment mapsize limit reached

@mujx mujx reopened this Aug 26, 2018
mujx added a commit that referenced this issue Aug 29, 2018
@mujx
Increase LMDB's map size (#413)
183975b
@unclechu
Copy link
Author

On nightly release 183975b now I can send regular unencrypted messages but I can send only single message to an E2EE room, this particular bug with E2EE room have been appeared even before this issue.

@unclechu
Copy link
Author

Testing new created E2EE room:
screenshot from 2018-08-29 19-01-39

[2018-08-29 19:00:27.493] [ui] [warning] updateUnreadMessageCount: unknown room_id !CfNzrVthKynLVbqEAY:matrix.org
type not found: {
  "content": {
    "guest_access": "can_join"
  },
  "event_id": "$153555841535657zizct:matrix.org",
  "origin_server_ts": 1535558415736,
  "sender": "@unclechu:matrix.org",
  "state_key": "",
  "type": "m.room.guest_access",
  "unsigned": {
    "age": 15380
  }
}
type not found: {
  "content": {
    "avatar_url": "",
    "displayname": "efie (IRC)",
    "is_direct": false,
    "membership": "join"
  },
  "event_id": "$15355584111100677EzIOA:matrix.org",
  "origin_server_ts": 1535558411673,
  "sender": "@freenode_efie:matrix.org",
  "state_key": "@freenode_efie:matrix.org",
  "type": "m.room.member",
  "unsigned": {
    "age": 19443
  }
}
type not found: {
  "content": {
    "creator": "@unclechu:matrix.org",
    "m.federate": true
  },
  "event_id": "$153555841235652OhfJs:matrix.org",
  "origin_server_ts": 1535558412383,
  "room_id": "!CfNzrVthKynLVbqEAY:matrix.org",
  "sender": "@unclechu:matrix.org",
  "state_key": "",
  "type": "m.room.create",
  "unsigned": {
    "age": 30860
  }
}
type not found: {
  "content": {
    "avatar_url": "",
    "displayname": "freimatz3 (IRC)",
    "is_direct": false,
    "membership": "join"
  },
  "event_id": "$15355584471101152KymEo:matrix.org",
  "origin_server_ts": 1535558447557,
  "sender": "@freenode_freimatz3:matrix.org",
  "state_key": "@freenode_freimatz3:matrix.org",
  "type": "m.room.member",
  "unsigned": {
    "age": 13507,
    "prev_sender": "@freenode_freimatz3:matrix.org",
    "replaces_state": "$1535521687758427jLNRB:matrix.org"
  }
}
type not found: {
  "content": {
    "avatar_url": "",
    "displayname": "",
    "is_direct": false,
    "membership": "leave"
  },
  "event_id": "$15355584531101252UCsrI:matrix.org",
  "origin_server_ts": 1535558453903,
  "sender": "@freenode_crose:matrix.org",
  "state_key": "@freenode_crose:matrix.org",
  "type": "m.room.member",
  "unsigned": {
    "age": 12764,
    "prev_sender": "@freenode_crose:matrix.org",
    "replaces_state": "$1535549754992113FRlQQ:matrix.org"
  }
}
[2018-08-29 19:01:13.484] [net] [info] enabled encryption on room (!CfNzrVthKynLVbqEAY:matrix.org)
[2018-08-29 19:01:16.908] [ui] [info] [wGEEPmTSum7l9dqOY6s9RnnUGcpSlDcZ] sending next queued message
[2018-08-29 19:01:17.575] [ui] [info] [wGEEPmTSum7l9dqOY6s9RnnUGcpSlDcZ] message was received by the server
[2018-08-29 19:01:18.597] [db] [info] mark room !CfNzrVthKynLVbqEAY:matrix.org as encrypted
type not found: {
  "content": {
    "algorithm": "m.megolm.v1.aes-sha2"
  },
  "event_id": "$1535558473400516fIJXR:matrix.org",
  "origin_server_ts": 1535558473286,
  "sender": "@unclechu:matrix.org",
  "state_key": "",
  "type": "m.room.encryption",
  "unsigned": {
    "age": 4793
  }
}
[2018-08-29 19:01:19.833] [ui] [info] [wGEEPmTSum7l9dqOY6s9RnnUGcpSlDcZ] removed message with sync
[2018-08-29 19:01:21.126] [ui] [info] [ZoU9sqpKVAvCHfuVgiIXvz46rFd9MnLI] sending next queued message
[2018-08-29 19:01:21.126] [ui] [info] [ZoU9sqpKVAvCHfuVgiIXvz46rFd9MnLI] sending encrypted event
[2018-08-29 19:01:21.127] [ui] [info] creating new outbound megolm session
[2018-08-29 19:01:21.150] [ui] [info] retrieved 1 members for !CfNzrVthKynLVbqEAY:matrix.org
[2018-08-29 19:01:21.706] [net] [info] CCPZLYDIWF
[2018-08-29 19:01:21.706] [net] [info]   curve25519 7xDsPNIdHMnIM8I24Uer+gRUHinn+Zc/bLKwiBLwalA
[2018-08-29 19:01:21.706] [net] [info]   ed25519 6xlDCYQH86PxhDJFZPk/bnxAG8liS1f3rpLJpzQQI6Q
[2018-08-29 19:01:21.706] [net] [info] CZHNCGIUIW
[2018-08-29 19:01:21.706] [net] [info]   curve25519 ttphBPXpykpTzidIxLPCI+jWz4FHtVH/IdChAw92QTY
[2018-08-29 19:01:21.706] [net] [info]   ed25519 nBJuoKatw2TlJQIftqdG87TdLwOieTeLckmuaOQRm/0
[2018-08-29 19:01:21.706] [net] [info] WMFYKBCROZ
[2018-08-29 19:01:21.706] [net] [info]   curve25519 WHN1nQYmTkhzJAt4G6AnpHI613wybH8lxnkkUMdsIRM
[2018-08-29 19:01:21.706] [net] [info]   ed25519 LBeAnYTohQkjSrsXssKvbxj5rYYkleNV40vM6SDS8jk
[2018-08-29 19:01:21.706] [net] [info] sending claim request for user @unclechu:matrix.org with 3 devices
[2018-08-29 19:01:22.264] [net] [info] claimed keys for @unclechu:matrix.org
[2018-08-29 19:01:22.268] [net] [info] CCPZLYDIWF :
 {
  "signed_curve25519:AAAAHw": {
    "key": "oNp2HO49rNn4N8JU93N+IfEYd3XeeI9doWWXCi4mvzw",
    "signatures": {
      "@unclechu:matrix.org": {
        "ed25519:CCPZLYDIWF": "mwAWeAvrOwhZsL3HolGn+OitvL9nz5C3Np4aD+F8mBXKWfJiCzIgboXoCMF1L3QS04cisUDcp4aksHAXd8FsAw"
      }
    }
  }
}
[2018-08-29 19:01:22.279] [net] [info] CZHNCGIUIW :
 {
  "signed_curve25519:AAAAHA": {
    "key": "8ikM9W2VAV2tPtFcOPziRdO0LvGZ7LR6mvmmCSt5F1M",
    "signatures": {
      "@unclechu:matrix.org": {
        "ed25519:CZHNCGIUIW": "H2PadnlNr4oy6aGgIa3qHmbdSARp2zpoliRI7LHRFlAJVXetyTeNYwd0m5kTrdDfx269nHY3iDGDF2CQwoomBw"
      }
    }
  }
}
[2018-08-29 19:01:22.286] [net] [info] WMFYKBCROZ :
 {
  "signed_curve25519:AAAARA": {
    "key": "JRbVjgAqRSRDyJ4HE0VGyQBmYKh/sob7Feavgggd40s",
    "signatures": {
      "@unclechu:matrix.org": {
        "ed25519:WMFYKBCROZ": "Qb/W9YD3UfS+Xr6AIrmtXLufoo7Hsr1QsqQI73kQam9KJFnCjYd1PINeZt4icFFEedeOhxuBkMqpGVRwDR3hAA"
      }
    }
  }
}
[2018-08-29 19:01:22.293] [net] [info] send_to_device: @unclechu:matrix.org
[2018-08-29 19:01:22.739] [crypto] [info] next message_index 1
[2018-08-29 19:01:23.308] [crypto] [info] received 1 to_device messages
[2018-08-29 19:01:23.308] [crypto] [info] sender    : @unclechu:matrix.org
[2018-08-29 19:01:23.308] [crypto] [info] sender_key: ttphBPXpykpTzidIxLPCI+jWz4FHtVH/IdChAw92QTY
[2018-08-29 19:01:23.308] [crypto] [info] type: OLM_PRE_KEY
[2018-08-29 19:01:23.308] [crypto] [info] attempt to decrypt message with 11 known session_ids
[2018-08-29 19:01:23.327] [crypto] [info] failed to decrypt olm message (0, ttphBPXpykpTzidIxLPCI+jWz4FHtVH/IdChAw92QTY) with 0Oay7YkHavr79a6b6tqJ21z+cs1BMTIy6KyUFMZ94bc: olm_decrypt: BAD_MESSAGE_MAC
[2018-08-29 19:01:23.328] [crypto] [info] failed to decrypt olm message (0, ttphBPXpykpTzidIxLPCI+jWz4FHtVH/IdChAw92QTY) with 2WnuB6lX0DTRN1ZPxYWw44/WbMMbYAOvYPoyqH9r60c: olm_decrypt: BAD_MESSAGE_MAC
[2018-08-29 19:01:23.329] [crypto] [info] failed to decrypt olm message (0, ttphBPXpykpTzidIxLPCI+jWz4FHtVH/IdChAw92QTY) with 7+P4AunZXGaA79B5xhFYssKBB6W/W5Mo7Q/g/3t3EBk: olm_decrypt: BAD_MESSAGE_MAC
[2018-08-29 19:01:23.330] [crypto] [info] failed to decrypt olm message (0, ttphBPXpykpTzidIxLPCI+jWz4FHtVH/IdChAw92QTY) with MAu2mYFz4MgNrMMuhykAlTL4KCFUOiWMK3tLUyYEMTc: olm_decrypt: BAD_MESSAGE_MAC
[2018-08-29 19:01:23.331] [crypto] [info] failed to decrypt olm message (0, ttphBPXpykpTzidIxLPCI+jWz4FHtVH/IdChAw92QTY) with QRIpLLO+AtKPqyypXPacU9h0l66XDvOp0ePONXLUEkg: olm_decrypt: BAD_MESSAGE_MAC
[2018-08-29 19:01:23.332] [crypto] [info] failed to decrypt olm message (0, ttphBPXpykpTzidIxLPCI+jWz4FHtVH/IdChAw92QTY) with WlqKcNPrBDPfDsLkCygKiM9uk4i+nZEZM4IxiyuqM8U: olm_decrypt: BAD_MESSAGE_MAC
[2018-08-29 19:01:23.333] [crypto] [info] failed to decrypt olm message (0, ttphBPXpykpTzidIxLPCI+jWz4FHtVH/IdChAw92QTY) with cc35HRuzaeU3hbVYXS8kdyloOWS/oiSDelHG5yFyHgI: olm_decrypt: BAD_MESSAGE_MAC
[2018-08-29 19:01:23.334] [crypto] [info] failed to decrypt olm message (0, ttphBPXpykpTzidIxLPCI+jWz4FHtVH/IdChAw92QTY) with eti8/8djMz97c9U58Yaw7SpuR7jcS+d6m6BptqlpK4Y: olm_decrypt: BAD_MESSAGE_MAC
[2018-08-29 19:01:23.335] [crypto] [info] failed to decrypt olm message (0, ttphBPXpykpTzidIxLPCI+jWz4FHtVH/IdChAw92QTY) with ooabu92U2McST1+9G5eUTxOO4ezOojBAoJ9x3xmxuIs: olm_decrypt: BAD_MESSAGE_MAC
[2018-08-29 19:01:23.335] [crypto] [info] failed to decrypt olm message (0, ttphBPXpykpTzidIxLPCI+jWz4FHtVH/IdChAw92QTY) with pbJBJr7l4tabIC/KlvIr6DBTCWhPIMHnkSpwhNcdpA0: olm_decrypt: BAD_MESSAGE_MAC
[2018-08-29 19:01:23.336] [crypto] [info] failed to decrypt olm message (0, ttphBPXpykpTzidIxLPCI+jWz4FHtVH/IdChAw92QTY) with sefXc/8zXbRQ6BsBNDtqplikwUuO59foMlYjUzmtmwE: olm_decrypt: BAD_MESSAGE_MAC
[2018-08-29 19:01:23.336] [crypto] [info] opening olm session with @unclechu:matrix.org
[2018-08-29 19:01:23.336] [crypto] [critical] failed to create inbound session with @unclechu:matrix.org: create_inbound_session_from: BAD_MESSAGE_KEY_ID
[2018-08-29 19:01:23.671] [ui] [info] [ZoU9sqpKVAvCHfuVgiIXvz46rFd9MnLI] message was received by the server
[2018-08-29 19:01:23.995] [crypto] [info] Could not find inbound megolm session (!CfNzrVthKynLVbqEAY:matrix.org, j2Lti2lJhy6hYf0bXFO+mIl7YxXW6Yq3GshQPxtCS8M, @unclechu:matrix.org)

@mujx
Copy link
Owner

mujx commented Aug 29, 2018

@unclechu Do you see any errors/warnings related to one-time keys in the logs? I suspect there might be some bad one time keys uploaded in the server.

@unclechu
Copy link
Author

@mujx I sent whole part of the log since I created new room. Do you mean if I see something above?

@mujx
Copy link
Owner

mujx commented Aug 29, 2018

Yes, you could grep for failed to upload one time keys.

@unclechu
Copy link
Author

I just restart nheko and here what I see:

λ ./nheko-nightly-x86_64.AppImage
shutdown: uninitializedshutdown: uninitialized

FilteredTextEdit(0x309bab0)  does not have a property named  "borderColor"
FilteredTextEdit(0x309bab0)  does not have a property named  "borderColor"
[2018-08-29 19:16:15.490] [db] [info] restoring state from cache
[2018-08-29 19:16:15.503] [db] [info] sessions restored
[2018-08-29 19:16:15.504] [db] [info] loading 150 rooms
[2018-08-29 19:16:15.529] [ui] [info] starting nheko 0.5.4-183975b
[2018-08-29 19:16:15.978] [crypto] [info] ed25519   : SOME-HASH
[2018-08-29 19:16:15.978] [crypto] [info] curve25519: SOME-ANOTHER-HASH
[2018-08-29 19:16:16.112] [ui] [info] initialize room list

@unclechu
Copy link
Author

After I sent a message to E2EE room and tried to send another (without success):

[2018-08-29 19:18:34.154] [crypto] [info] Could not find inbound megolm session (!ROOM-ID:matrix.org, SOME-HASH, @unclechu:matrix.org)

@mujx
Copy link
Owner

mujx commented Aug 29, 2018

I meant to search in the nheko.log file in ~/.cache/nheko for the following string

failed to upload one time keys

@unclechu
Copy link
Author

@mujx Nothing found by:

cat nheko*.log | grep -i 'failed to upload one time keys'

@unclechu
Copy link
Author

#422 is blocker to check if this bug disappears after login to new session.

@unclechu
Copy link
Author

@mujx After new sync everything is okay, I'm also able to see my own messages after restart.
Maybe this issue supposed to be kept open until some mechanism will be implemented to solve this issue automatically?

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@unclechu @mujx