Berty Daemon error messages when sending and recieving messages from a group

[LFGaming]

Is there an existing issue for this?

• I have searched the existing issues

Berty product

CLI tools (berty mini, daemon, etc.)

Berty product version

version n/a go go1.18.5

OS

Linux

OS version

Ubuntu 20.04.5 LTS

Device

No response

Steps to reproduce

1. start berty daemon
2. open a phone (we'll call it phone A) in a group with at least one other phone in it and the berty daemon.
3. send a message from Phone A to the group with berty daemon on, and Phone B offline.
4. close the app on phone A, then open the app on Phone B.
5. recieve the message (or send a message from Phone B to force the message getting send to it).
6. get a lot off errors in the berty deamon.

Current behavior

at this point in time I get a lot off errors when doing the above.
in the outputt below i will place ##### with info for when what happens.

  Berty: n/a                             Go: go1.18.5
  PID: 725           Arch: amd64         OS: linux
  P2P peers: 29                          Hostname: Wolf
  Accounts=1  Contacts=5  Convs=7  Members=18 Devices=13
  Work dir: /home/luke
2023-03-10T18:21:13.902+0100    ERROR   bty.pt.req-mngr         weshnet@v1.1.1/contact_request_manager.go:211   unable to handle incoming contact request       {"error": "invalid contact information format: ErrContactRequestIncomingAlreadyReceived(#1204)"}
2023-03-10T18:21:13.963+0100    ERROR   bty.odb-dc              directchannel/channel.go:61     invalid buffer length   {"error": "short buffer"}
2023-03-10T18:21:14.209+0100    INFO    bty.peering             ipfsutil/peering.go:119 peer added      {"peer": "09712a08b8096dc5b52f9c3ffc9bc1ffe915bf53aacf29d4c66bfe178a70b6d4", "addrs": ["/ip4/127.0.0.1/udp/38836/quic","/ip4/192.168.0.129/udp/38836/quic","/ble/12D3KooWEzmsDoLnjD2kJnfB993kmLdzv7As8RkFgLmkqtrVf6CL"]}
2023-03-10T18:21:15.921+0100    INFO    bty.odb                 weshnet@v1.1.1/api_event.go:211 service - message store - sent 1 event from log subscription    {"group-id": "eed260c04b4042cb54a3a8f6a4337a232a26617fb26262f9893a19e2794170f7"}
2023-03-10T18:21:15.921+0100    INFO    bty.odb                 weshnet@v1.1.1/api_event.go:211 service - message store - sent 1 event from log subscription    {"group-id": "eed260c04b4042cb54a3a8f6a4337a232a26617fb26262f9893a19e2794170f7"}
2023-03-10T18:21:15.922+0100    ERROR   bty.gorm                messengerdb/db.go:926   trace   {"error": "record not found", "elapsed": "61.116µs", "rows": 0, "sql": "SELECT * FROM `interactions` WHERE `interactions`.`cid` = \"bafyreig3hapjuci7lrrflxzfzowz2x5sj3uowsbmpokg6ga2u22jrabvvi\" ORDER BY `interactions`.`cid` LIMIT 1"}
2023-03-10T18:21:15.931+0100    INFO    bty.odb                 weshnet@v1.1.1/api_event.go:211 service - message store - sent 1 event from log subscription    {"group-id": "eed260c04b4042cb54a3a8f6a4337a232a26617fb26262f9893a19e2794170f7"}
2023-03-10T18:21:15.931+0100    INFO    bty.odb                 weshnet@v1.1.1/api_event.go:211 service - message store - sent 1 event from log subscription    {"group-id": "eed260c04b4042cb54a3a8f6a4337a232a26617fb26262f9893a19e2794170f7"}
2023-03-10T18:21:16.794+0100    INFO    bty.odb                 weshnet@v1.1.1/api_event.go:211 service - message store - sent 1 event from log subscription    {"group-id": "eed260c04b4042cb54a3a8f6a4337a232a26617fb26262f9893a19e2794170f7"}
2023-03-10T18:21:16.794+0100    INFO    bty.odb                 weshnet@v1.1.1/api_event.go:211 service - message store - sent 1 event from log subscription    {"group-id": "eed260c04b4042cb54a3a8f6a4337a232a26617fb26262f9893a19e2794170f7"}
###########
message from Phone A send
###########

###########
Phone B starting the app
###########
2023-03-10T18:22:09.431+0100    INFO    bty.peering             ipfsutil/peering.go:119 peer added      {"peer": "847a555e50d045a6cefa35fe577e685b657d6246a200870f4dd978004bf83245", "addrs": ["/ble/12D3KooWSMgRgzngiuzGhTjewN8UtxXD1WY8aygEtzY7cHaihdSy","/mc/12D3KooWSMgRgzngiuzGhTjewN8UtxXD1WY8aygEtzY7cHaihdSy","/ip4/192.0.0.1/udp/63026/quic","/ip4/127.0.0.1/udp/63026/quic"]}
2023-03-10T18:22:09.508+0100    INFO    bty.odb                 weshnet@v1.1.1/api_event.go:121 service - metadata store - sent 1 event from log subscription   {"group-id": "85814d75aa9099d407183a1259522fa74ddd6034ee9e8dd2fe5307f2521d267e"}
2023-03-10T18:22:09.509+0100    INFO    bty.msg.hdl             messengerpayloads/handlers.go:132       Received protocol event in MessengerService     {"a": "85814d75aa9099d407183a1259522fa74ddd6034ee9e8dd2fe5307f2521d267e", "tyberLogType": "step", "step": {"parentTraceID":"msgrcvd-bafyreic6adhwcxiex7qxjtexkivxnf2e5nzrcypgejjb3wlhplqff7ycvm","details":[{"name":"Type","description":"EventTypeAccountContactRequestOutgoingSent"}],"status":"succeeded","endTrace":false,"updateTraceName":"","forceReopen":true}}
2023-03-10T18:22:09.509+0100    ERROR   bty.msg.tyber           tyber/log.go:16 Database transaction failed     {"tyberLogType": "step", "step": {"parentTraceID":"msgrcvd-bafyreic6adhwcxiex7qxjtexkivxnf2e5nzrcypgejjb3wlhplqff7ycvm","details":[{"name":"Error","description":"ErrDBAddContactRequestOutgoingSent(#2102): ErrDBAddContactRequestOutgoingSent(#2102): nothing found"}],"status":"succeeded","endTrace":false,"updateTraceName":"","forceReopen":false}}
2023-03-10T18:22:09.509+0100    ERROR   bty.msg.hdl.tyber       tyber/log.go:16 Failed to handle protocol event {"a": "85814d75aa9099d407183a1259522fa74ddd6034ee9e8dd2fe5307f2521d267e", "tyberLogType": "step", "step": {"parentTraceID":"msgrcvd-bafyreic6adhwcxiex7qxjtexkivxnf2e5nzrcypgejjb3wlhplqff7ycvm","details":[{"name":"Error","description":"ErrDBWrite(#108): ErrDBAddContactRequestOutgoingSent(#2102): ErrDBAddContactRequestOutgoingSent(#2102): nothing found"}],"status":"failed","endTrace":true,"updateTraceName":"","forceReopen":false}}
2023-03-10T18:22:09.840+0100    ERROR   bty.odb-dc              directchannel/channel.go:61     invalid buffer length   {"error": "short buffer"}
2023-03-10T18:22:09.849+0100    ERROR   bty.odb-dc              directchannel/channel.go:61     invalid buffer length   {"error": "short buffer"}
2023-03-10T18:22:10.510+0100    ERROR   bty.pt.req-mngr.tyber   tyber/log.go:16 Error while Enqueue contact request: esjEohGaCWGxHCQcpkssIm5fkxrkZgFbkgzAiuSU-mY        {"tyberLogType": "step", "step": {"parentTraceID":"c1970316-f3af-44a2-b928-658f1524c13f","details":[{"name":"Error","description":"unable to connect: failed to dial 12D3KooWSMgRgzngiuzGhTjewN8UtxXD1WY8aygEtzY7cHaihdSy:\n  * [/ip6/2001:bc8:2610:4200::/tcp/6363/quic/p2p/12D3KooWBoShE6E6uXveQWVunK7AJk6UReDBmiui5qFYWbug1Nf9/p2p-circuit] error opening relay circuit: HOP_NO_CONN_TO_DST (260)\n  * [/ip4/51.159.21.214/tcp/6363/p2p/12D3KooWBoShE6E6uXveQWVunK7AJk6UReDBmiui5qFYWbug1Nf9/p2p-circuit] concurrent active dial through the same relay failed with a protocol error\n  * [/ip4/51.159.21.214/udp/6363/quic/p2p/12D3KooWBoShE6E6uXveQWVunK7AJk6UReDBmiui5qFYWbug1Nf9/p2p-circuit] concurrent active dial through the same relay failed with a protocol error\n  * [/ip6/2001:bc8:2610:4200::/udp/6363/quic/p2p/12D3KooWBoShE6E6uXveQWVunK7AJk6UReDBmiui5qFYWbug1Nf9/p2p-circuit] concurrent active dial through the same relay failed with a protocol error\n  * [/ip6/2001:bc8:2610:4200::/tcp/6363/p2p/12D3KooWBoShE6E6uXveQWVunK7AJk6UReDBmiui5qFYWbug1Nf9/p2p-circuit] concurrent active dial through the same relay failed with a protocol error\n  * [/ip4/51.15.25.224/udp/6363/quic/p2p/12D3KooWAHcEz4K5XAgRDav9fLuhiRY2wuXip385EmT5RoRkCmjr/p2p-circuit] error opening relay circuit: HOP_NO_CONN_TO_DST (260)\n  * [/ip4/51.15.25.224/tcp/6363/p2p/12D3KooWAHcEz4K5XAgRDav9fLuhiRY2wuXip385EmT5RoRkCmjr/p2p-circuit] concurrent active dial through the same relay failed with a protocol error"}],"status":"failed","endTrace":true,"updateTraceName":"","forceReopen":false}}
###########
Phone B online
###########

###########
Phone B (sending message to recieve other messages)
###########
2023-03-10T18:23:14.711+0100    INFO    bty.odb                 weshnet@v1.1.1/api_event.go:211 service - message store - sent 1 event from log subscription    {"group-id": "eed260c04b4042cb54a3a8f6a4337a232a26617fb26262f9893a19e2794170f7"}
2023-03-10T18:23:14.711+0100    INFO    bty.odb                 weshnet@v1.1.1/api_event.go:211 service - message store - sent 1 event from log subscription    {"group-id": "eed260c04b4042cb54a3a8f6a4337a232a26617fb26262f9893a19e2794170f7"}
2023-03-10T18:23:14.712+0100    ERROR   bty.gorm                messengerdb/db.go:926   trace   {"error": "record not found", "elapsed": "51.368µs", "rows": 0, "sql": "SELECT * FROM `interactions` WHERE `interactions`.`cid` = \"bafyreifijdyg2qg35e52nv2fzcnxqkls274xvdzioe6e4w356brao5nhpu\" ORDER BY `interactions`.`cid` LIMIT 1"}
2023-03-10T18:23:14.723+0100    INFO    bty.odb                 weshnet@v1.1.1/api_event.go:211 service - message store - sent 1 event from log subscription    {"group-id": "eed260c04b4042cb54a3a8f6a4337a232a26617fb26262f9893a19e2794170f7"}
2023-03-10T18:23:14.723+0100    INFO    bty.odb                 weshnet@v1.1.1/api_event.go:211 service - message store - sent 1 event from log subscription    {"group-id": "eed260c04b4042cb54a3a8f6a4337a232a26617fb26262f9893a19e2794170f7"}
2023-03-10T18:23:15.290+0100    INFO    bty.odb                 weshnet@v1.1.1/api_event.go:211 service - message store - sent 1 event from log subscription    {"group-id": "eed260c04b4042cb54a3a8f6a4337a232a26617fb26262f9893a19e2794170f7"}
2023-03-10T18:23:15.290+0100    INFO    bty.odb                 weshnet@v1.1.1/api_event.go:211 service - message store - sent 1 event from log subscription    {"group-id": "eed260c04b4042cb54a3a8f6a4337a232a26617fb26262f9893a19e2794170f7"}

Expected behavior

I would expect it should not send errors?

Other

No response

[jefft0]

See issue #4702 . This is a known problem where the logger prints ERROR for many normal processes. Closing this issue in favor of that one.