Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

databroker-cli PoisonError on CentOS / AutoSD 9 #634

Closed
mikehaller opened this issue Aug 2, 2023 · 8 comments
Closed

databroker-cli PoisonError on CentOS / AutoSD 9 #634

mikehaller opened this issue Aug 2, 2023 · 8 comments
Labels
bug Something isn't working Databroker Issues related to databroker (core) Databroker-cli

Comments

@mikehaller
Copy link

When running the Kuksa.VAL Databroker CLI via podman on the Nightly builds of CentOS / AutoSD 9, I get an error when subscribing to vehicle signals:

thread 'tokio-runtime-worker' panicked at 'attempt to divide by zero'

Environment:

The following error occurs when subscribing to vehicle signals.

Full output:

podman run --network host -it --rm ghcr.io/eclipse/kuksa.val/databroker-cli:0.4k host -it --rm ghcr.io/eclipse/kuksa.val/databroker-cli:0.4
Trying to pull ghcr.io/eclipse/kuksa.val/databroker-cli:0.4...
Getting image source signatures
Writing manifest to image destination

  ⠀⠀⠀⢀⣤⣶⣾⣿⢸⣿⣿⣷⣶⣤⡀
  ⠀⠀⣴⣿⡿⠋⣿⣿⠀⠀⠀⠈⠙⢿⣿⣦⠀
  ⠀⣾⣿⠋⠀⠀⣿⣿⠀⠀⣶⣿⠀⠀⠙⣿⣷   
  ⣸⣿⠇⠀⠀⠀⣿⣿⠠⣾⡿⠃⠀⠀⠀⠸⣿⣇⠀⠀⣶⠀⣠⡶⠂⠀⣶⠀⠀⢰⡆⠀⢰⡆⢀⣴⠖⠀⢠⡶⠶⠶⡦⠀⠀⠀⣰⣶⡀
  ⣿⣿⠀⠀⠀⠀⠿⢿⣷⣦⡀⠀⠀⠀⠀⠀⣿⣿⠀⠀⣿⢾⣏⠀⠀⠀⣿⠀⠀⢸⡇⠀⢸⡷⣿⡁⠀⠀⠘⠷⠶⠶⣦⠀⠀⢠⡟⠘⣷
  ⢹⣿⡆⠀⠀⠀⣿⣶⠈⢻⣿⡆⠀⠀⠀⢰⣿⡏⠀⠀⠿⠀⠙⠷⠄⠀⠙⠷⠶⠟⠁⠀⠸⠇⠈⠻⠦⠀⠐⠷⠶⠶⠟⠀⠠⠿⠁⠀⠹⠧
  ⠀⢿⣿⣄⠀⠀⣿⣿⠀⠀⠿⣿⠀⠀⣠⣿⡿
  ⠀⠀⠻⣿⣷⡄⣿⣿⠀⠀⠀⢀⣠⣾⣿⠟    databroker-cli                
  ⠀⠀⠀⠈⠛⠇⢿⣿⣿⣿⣿⡿⠿⠛⠁     v0.4.0                        

Successfully connected to http://127.0.0.1:55555/
subscsubscribe SELSELECT VehVehicle.Speed

[subscribe]  OK  
[1] Vehicle.Speed: 6.00
;37mSubscription is now running in the background. Received data is identified by [1].
thread 'tokio-runtime-worker' panicked at 'attempt to divide by zero', /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/linefeed-0.6.0/src/writer.rs:887:28
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: PoisonError { .. }', /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/linefeed-0.6.0/src/terminal.rs:191:38
thread 'tokio-runtime-worker' panicked at 'Terminal::lock_writer: PoisonError { .. }', /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/mortal-0.2.4/src/unix/terminal.rs:296:27
[root@localhost ~]#

Output of podman ps:

[root@localhost ~]# podman ps
CONTAINER ID  IMAGE                                                                                                                        COMMAND               CREATED        STATUS        PORTS       NAMES
afe347ba83ec  ghcr.io/eclipse/kuksa.val/databroker:0.3.0                                                                                                         4 minutes ago  Up 4 minutes              databroker
52b38fca6323  docker.io/library/eclipse-mosquitto:latest                                                                                   /usr/sbin/mosquit...  4 minutes ago  Up 4 minutes              mosquitto
b1ed9552731c  ghcr.io/eclipse-leda/leda-contrib-vehicle-update-manager/vehicleupdatemanager:main-1d8dca55a755c4b3c7bc06eabfa06ad49e068a48  /bin/sh -c ./upda...  4 minutes ago  Up 4 minutes              vum
226c0ff10cca  ghcr.io/eclipse/kuksa.val.feeders/dbc2val:v0.1.1                                                                             ./dbcfeeder-exe       3 minutes ago  Up 3 minutes              sad_lumiere
d8881ec03001  ghcr.io/eclipse/kuksa.val.services/hvac_service:v0.1.0                                                                       ./hvacservice-exe     3 minutes ago  Up 3 minutes              gifted_benz
2cb05d53ca07  ghcr.io/boschglobal/kuksa.val.services/seat_service:v0.3.0                                                                   ./val_start.sh        3 minutes ago  Up 3 minutes              epic_mayer
63345197ebff  ghcr.io/eclipse-leda/leda-example-applications/leda-example-carsim:v0.0.1                                                    ./carsim_runner-e...  3 minutes ago  Up 3 minutes              suspicious_khorana
fbe334e8c688  ghcr.io/eclipse-leda/leda-example-applications/leda-example-driversim:v0.0.1                                                 ./driver_runner-e...  3 minutes ago  Up 3 minutes              lucid_greider
[root@localhost ~]#

The whole setup is described here as a Docker + QEMU setup:
https://github.com/SoftwareDefinedVehicle/leda-distro-fork/tree/rhivos/resources/centos-autosd
@lukasmittag lukasmittag added bug Something isn't working Databroker Issues related to databroker (core) Databroker-cli labels Aug 3, 2023
@mikehaller
Copy link
Author

Running without any feeder for Vehicle.Speed, the error still occurs when using RUST_BACKTRACE=1, but it disappears when running with RUST_BACKTRACE=full.

When actual data providers are deployed (carsim, driversim), the error occurs and a full stacktrace can be received when using RUST_BACKTRACE=full.

Note: The corrupted select statement is because I copied from the qemu serial console. The actual statements were of course correct.

Output with RUST_BACKTRACE=1:

podman run --network host --detach --name databroker ghcr.io/eclipse/kuksa.val/databroker:0.3.0
podman run --network host -it --rm --env "RUST_BACKTRACE=1" ghcr.io/eclipse/kuksa.val/databroker-cli:0.4

Subscription is now running in the background. Received data is identified by [1].
thread 'tokio-runtime-worker' panicked at 'attempt to divide by zero', /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/linefeed-0.6.0/src/writer.rs:887:28
stack backtrace:
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: PoisonError { .. }', /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/linefeed-0.6.0/src/terminal.rs:191:38
stack backtrace:
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
thread 'tokio-runtime-worker' panicked at 'Terminal::lock_writer: PoisonError { .. }', /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/mortal-0.2.4/src/unix/terminal.rs:296:27
stack backtrace:
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

Output with RUST_BACKTRACE=full: No error occurs

podman run --network host --detach --name databroker ghcr.io/eclipse/kuksa.val/databroker:0.3.0
podman run --network host -it --rm --env "RUST_BACKTRACE=full" ghcr.io/eclipse/kuksa.val/databroker-cli:0.4

[root@localhost ~]# podman run --network host -it --rm --env "RUST_BACKTRACE=full" ghcr.io/eclipse/kuksa.val/databroker-cli:0.4
  ⠀⠀⠀⢀⣤⣶⣾⣿⢸⣿⣿⣷⣶⣤⡀
  ⠀⠀⣴⣿⡿⠋⣿⣿⠀⠀⠀⠈⠙⢿⣿⣦⠀
  ⠀⣾⣿⠋⠀⠀⣿⣿⠀⠀⣶⣿⠀⠀⠙⣿⣷   
  ⣸⣿⠇⠀⠀⠀⣿⣿⠠⣾⡿⠃⠀⠀⠀⠸⣿⣇⠀⠀⣶⠀⣠⡶⠂⠀⣶⠀⠀⢰⡆⠀⢰⡆⢀⣴⠖⠀⢠⡶⠶⠶⡦⠀⠀⠀⣰⣶⡀
  ⣿⣿⠀⠀⠀⠀⠿⢿⣷⣦⡀⠀⠀⠀⠀⠀⣿⣿⠀⠀⣿⢾⣏⠀⠀⠀⣿⠀⠀⢸⡇⠀⢸⡷⣿⡁⠀⠀⠘⠷⠶⠶⣦⠀⠀⢠⡟⠘⣷
  ⢹⣿⡆⠀⠀⠀⣿⣶⠈⢻⣿⡆⠀⠀⠀⢰⣿⡏⠀⠀⠿⠀⠙⠷⠄⠀⠙⠷⠶⠟⠁⠀⠸⠇⠈⠻⠦⠀⠐⠷⠶⠶⠟⠀⠠⠿⠁⠀⠹⠧
  ⠀⢿⣿⣄⠀⠀⣿⣿⠀⠀⠿⣿⠀⠀⣠⣿⡿
  ⠀⠀⠻⣿⣷⡄⣿⣿⠀⠀⠀⢀⣠⣾⣿⠟    databroker-cli                
  ⠀⠀⠀⠈⠛⠇⢿⣿⣿⣿⣿⡿⠿⠛⠁     v0.4.0                        

Successfully connected to http://127.0.0.1:55555/
subsubscribe SELSELECT VehVehicle.SpeVehicle.Speed 

[subscribe]  OK  
Subscription is now running in the background. Received data is identified by [1].[1] Vehicle.Speed: ( NotAvailable )

sdv.databroker.v1 >  
sdv.databroker.v1 >  
quitdatabroker.v1 >  
Bye bye!

When running a provider for Vehicle.Speed, the following happens:

podman run --network host --detach --name databroker ghcr.io/eclipse/kuksa.val/databroker:0.3.0
podman run --detach --network host --env "DATABROKER_ADDRESS=localhost:55555" ghcr.io/eclipse-leda/leda-example-applications/leda-example-carsim:v0.0.1
podman run --detach --network host --env "DATABROKER_ADDRESS=localhost:55555" ghcr.io/eclipse-leda/leda-example-applications/leda-example-driversim:v0.0.1

podman run --network host -it --rm --env "RUST_BACKTRACE=full" ghcr.io/eclipse/kuksa.val/databroker-cli:0.4

Successfully connected to http://127.0.0.1:55555/
subssubscribe selSELECT vehVehicle.speVehicle.Speed 

[subscribe]  OK  
Subscription is now running in the background. Received data is identified by [1].
thread 'tokio-runtime-worker' panicked at 'attempt to divide by zero', /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/linefeed-0.6.0/src/writer.rs:887:28
stack backtrace:
   0:     0x7f3a4d645255 - <unknown>
   1:     0x7f3a4d54003f - <unknown>
   2:     0x7f3a4d621320 - <unknown>
   3:     0x7f3a4d646cff - <unknown>
   4:     0x7f3a4d646585 - <unknown>
   5:     0x7f3a4d647494 - <unknown>
   6:     0x7f3a4d646f53 - <unknown>
   7:     0x7f3a4d646ee6 - <unknown>
   8:     0x7f3a4d646ed1 - <unknown>
   9:     0x7f3a4d4a80a2 - <unknown>
  10:     0x7f3a4d4a8272 - <unknown>
  11:     0x7f3a4d4caadb - <unknown>
  12:     0x7f3a4d4d2720 - <unknown>
  13:     0x7f3a4d5043f5 - <unknown>
  14:     0x7f3a4d4c2e31 - <unknown>
  15:     0x7f3a4d64f784 - <unknown>
  16:     0x7f3a4d658167 - <unknown>
  17:     0x7f3a4d652b25 - <unknown>
  18:     0x7f3a4d6523fb - <unknown>
  19:     0x7f3a4d653a25 - <unknown>
  20:     0x7f3a4d647f95 - <unknown>
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: PoisonError { .. }', /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/linefeed-0.6.0/src/terminal.rs:191:38
stack backtrace:
   0:     0x7f3a4d645255 - <unknown>
   1:     0x7f3a4d54003f - <unknown>
   2:     0x7f3a4d621320 - <unknown>
   3:     0x7f3a4d646cff - <unknown>
   4:     0x7f3a4d646585 - <unknown>
   5:     0x7f3a4d647494 - <unknown>
   6:     0x7f3a4d646f82 - <unknown>
   7:     0x7f3a4d646ee6 - <unknown>
   8:     0x7f3a4d646ed1 - <unknown>
   9:     0x7f3a4d4a80a2 - <unknown>
  10:     0x7f3a4d4a8572 - <unknown>
  11:     0x7f3a4d576f5e - <unknown>
  12:     0x7f3a4d4d1f3a - <unknown>
  13:     0x7f3a4d4fe63b - <unknown>
  14:     0x7f3a4d4ec6d4 - <unknown>
  15:     0x7f3a4d4b4941 - <unknown>
  16:     0x7f3a4d505073 - <unknown>
thread 'tokio-runtime-worker' panicked at 'Terminal::lock_writer: PoisonError { .. }', /root/.cargo/registry/src/index.crates.io-6f17d22bba15001f/mortal-0.2.4/src/unix/terminal.rs:296:27
stack backtrace:
   0:     0x7f3a4d645255 - <unknown>
   1:     0x7f3a4d54003f - <unknown>
   2:     0x7f3a4d621320 - <unknown>
   3:     0x7f3a4d646cff - <unknown>
   4:     0x7f3a4d646585 - <unknown>
   5:     0x7f3a4d647494 - <unknown>
   6:     0x7f3a4d646f82 - <unknown>
   7:     0x7f3a4d646ee6 - <unknown>
   8:     0x7f3a4d646ed1 - <unknown>
   9:     0x7f3a4d4a80a2 - <unknown>
  10:     0x7f3a4d4a8572 - <unknown>
  11:     0x7f3a4d5863fa - <unknown>
  12:     0x7f3a4d4b950a - <unknown>
  13:     0x7f3a4d4bba56 - <unknown>
  14:     0x7f3a4d4bcc82 - <unknown>
  15:     0x7f3a4d503bb8 - <unknown>
  16:     0x7f3a4d4c3060 - <unknown>
  17:     0x7f3a4d64f784 - <unknown>
  18:     0x7f3a4d658167 - <unknown>
  19:     0x7f3a4d652b25 - <unknown>
  20:     0x7f3a4d6523fb - <unknown>
  21:     0x7f3a4d653a25 - <unknown>
  22:     0x7f3a4d647f95 - <unknown>
[root@localhost ~]#

@mikehaller
Copy link
Author

For sake of completeness, not sure if relevant:

[root@localhost ~]# cat /etc/os-release 
NAME="CentOS AutoSD"
VERSION="9"
ID="AutoSD"
ID_LIKE="rhel fedora"
VERSION_ID="9"
PLATFORM_ID="platform:el9"
PRETTY_NAME="CentOS AutoSD 9"
ANSI_COLOR="0;31"
LOGO="fedora-logo-icon"
CPE_NAME="cpe:/o:centos:autosd:9"
HOME_URL="https://centos.org/"
BUG_REPORT_URL="https://bugzilla.redhat.com/"
REDHAT_SUPPORT_PRODUCT="Red Hat Enterprise Linux 9"
REDHAT_SUPPORT_PRODUCT_VERSION="CentOS AutoSD"

[root@localhost ~]# cat /etc/build-info 
RELEASE="nightly"
UUID="947941502.247784c5"
TIMESTAMP="2023-07-27 23:14:19.854066"
IMAGE_NAME="ostree"
IMAGE_TARGET="qemu"

@lukasmittag
Copy link
Contributor

Regarding the issue. I could reproduce the error with databroker v0.3.0 and databroker-cli 0.4 on RHIVOS.
What I then did is:

  • ran databroker:master image with databroker-cli:0.4 -> error persists
  • ran databroker:master image with databroker-cli:master -> error solved
  • ran databroker:0.3.0 with databroker-cli:master -> error solved

It seems that the error is only there in databroker-cli and is solved with version greater than 0.4.

@argerus @SebastianSchildt how much investigation should we do? Error is only present on RHIVOS on my linux setup it works fine.

@SebastianSchildt
Copy link
Contributor

At least the error seems scary enough, that we might want to know what happens.

In the cases the error happens, does it also happen when building the binaries (instead of using the dockers), and building in debug mode ( I think just omitting --release in Cargo build/run commandline should to the trick.)

Can you try @lukasmittag , I would hope, doing so would yield a better stacktrace then the one provided by @mikehaller

@argerus
Copy link
Contributor

argerus commented Aug 17, 2023 •
edited
Loading

Ok so @lukasmittag built a non-stripped databroker-cli binary which produced the following (relevant) part of the backtrace.

thread 'tokio-runtime-worker' panicked at 'attempt to divide by zero', [...]/linefeed-0.6.0/src/writer.rs:887:28

This line in the linefeed library looks like this:

        let prefix_lines = self.prompt_prefix_len / self.screen_size.columns;

So the root cause seems to be that the the system/terminal emulator is reporting a screen size of 0 columns. This causes a divide by zero in the library (linefeed) used by databroker-cli, hence the panic.

It is evident that the terminal is behaving erratically when using the QEMU serial console (not just when using databroker-cli) and the panic could not be reproduced when interacting with the QEMU VM using ssh instead.

So I guess there are a couple of options to fix this:

  • Fix the weird behaviour of the QEMU serial console.
  • Fix the "bug" in the linefeed library.
  • Use ssh to connect to the VM instead.

@SebastianSchildt
Copy link
Contributor

  • Fix the weird behaviour of the QEMU serial console.
  • Fix the "bug" in the linefeed library.

AS a first/intermediate step, can any of you REPORT those bugs in the upstream projects (I would assume linefeed defintely is a bug, as I would expect for serial/uart terminals you never have get an "official" column size (their is just no interface), unless the client decides "I assume this is a 80 column VT100"

@SebastianSchildt
Copy link
Contributor

Ping

@argerus Can you try to raise an issue with linefeed upstream? I don't think we can or need to fix it, but whatever they "intent" on such terminals, I guess they would not want to crash

@mikehaller As a workaround did you try whether setting some TERM variable before going into shell or using sttyand or starting another shell inside the session helps? See https://unix.stackexchange.com/questions/106644/how-to-change-the-width-of-remote-serial-console

@erikbosch
Copy link
Contributor

We are about to archive this repo soon. If you consider this issue as important please file a new issue at one of the new Kuksa repos at https://github.com/eclipse-kuksa

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working Databroker Issues related to databroker (core) Databroker-cli
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@mikehaller @argerus @SebastianSchildt @erikbosch @lukasmittag