MERG CBUS/VLCB hardware support

General
121

Moin Reinder,

I have narrowed down the problem.

I use the hub from JMRI with 127.0.0.1 5550 and set the hub of traintastic to 127.0.0.1 5551. The CANUSB4 is connected to JMRI.

2026-04-10 18:59:50.323030 cbus_1 I2007: New hub connection (127.0.0.1:46092)
2026-04-10 18:59:52.602634 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 18:59:56.796441 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:00.990036 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:05.183985 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:09.377417 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:13.571259 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:17.764774 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:21.958608 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:26.152165 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:30.345910 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:34.539651 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:38.733306 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:42.927051 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:47.120661 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:51.314401 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:55.508150 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:00:59.701801 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:01:03.895485 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:01:08.089297 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:01:12.282864 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:01:16.476578 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:01:20.670089 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:01:24.863946 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:01:29.057587 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:01:33.251123 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:01:37.441942 cbus_1 D2002: RX: DSPD session=2 speed=2 direction=fwd [47 02 82]
2026-04-10 19:01:37.444755 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:01:37.592449 cbus_1 D2002: RX: DSPD session=2 speed=4 direction=fwd [47 02 84]
2026-04-10 19:01:37.742358 cbus_1 D2002: RX: DSPD session=2 speed=6 direction=fwd [47 02 86]
2026-04-10 19:01:37.923029 cbus_1 D2002: RX: DSPD session=2 speed=8 direction=fwd [47 02 88]
2026-04-10 19:01:38.386317 cbus_1 D2002: RX: DSPD session=2 speed=7 direction=fwd [47 02 87]
2026-04-10 19:01:38.523420 cbus_1 D2002: RX: DSPD session=2 speed=5 direction=fwd [47 02 85]
2026-04-10 19:01:38.687100 cbus_1 D2002: RX: DSPD session=2 speed=3 direction=fwd [47 02 83]
2026-04-10 19:01:39.610676 cbus_1 D2002: RX: DSPD session=2 speed=0 direction=fwd [47 02 80]
2026-04-10 19:01:41.638642 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:01:44.402786 cbus_1 D2002: RX: DSPD session=2 speed=0 direction=fwd [47 02 80]
2026-04-10 19:01:45.832325 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:01:50.025989 cbus_1 D2002: RX: DKEEP session=2 [23 02]

I see all messages with Traintastic, no problems. And I have a telnet connection to 127.0.0.1 5551:

tom@amarok:~/projects/PIC/CANUSB4-ISO$ telnet 127.0.0.1 5551
Trying 127.0.0.1…
Connected to 127.0.0.1.
Escape character is ‘^]’.
:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;
:SB020N2302;
:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N470282;:SB020N2302;:SB020N470284;:SB020N470286;:SB020N470288;:SB020N470287;:SB020N470285;:SB020N470283;:SB020N470280;:SB020N2302;:SB020N470280;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;:SB020N2302;

After this I set Traintastic to /dev/ACM0:

tom@amarok:~/projects/linux/traintastic/server/build$ ./traintastic-server
2026-04-10 19:04:19.336782 traintastic I1001: Traintastic v0.4.0-dev
2026-04-10 19:04:19.336831 traintastic I1006: boost 1.81.0
2026-04-10 19:04:19.336840 traintastic I1007: nlohmann::json 3.10.5
2026-04-10 19:04:19.336858 traintastic I1008: libarchive 3.6.2 zlib/1.2.13 liblzma/5.4.1 bz2lib/1.0.8 liblz4/1.9.4 libzstd/1.5.4
2026-04-10 19:04:19.336867 traintastic I1009: zlib 1.2.13
2026-04-10 19:04:19.336876 traintastic I9002: Lua 5.4.4  Copyright (C) 1994-2022 Lua.org, PUC-Rio
2026-04-10 19:04:19.336974 settings N1008: Loaded settings
2026-04-10 19:04:19.337007 traintastic I1005: Building world index
2026-04-10 19:04:19.349415 traintastic N1027: Loaded world: Ferbach-Laubach
2026-04-10 19:04:19.349499 server N1005: Discovery enabled
2026-04-10 19:04:19.349550 server N1007: Listening at 127.0.0.1:5740
2026-04-10 19:04:21.395451 client[127.0.0.1:36674] I1003: New connection
2026-04-10 19:04:23.798768 world N1012: Communication: enabled
2026-04-10 19:04:23.799723 cbus_1 D2001: TX: QNN [0D]
2026-04-10 19:04:23.799746 cbus_1 N2008: Hub listening at 127.0.0.1:5551
2026-04-10 19:04:23.799764 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:04:23.799771 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:04:23.799781 cbus_1 D2002: RX: DKEEP session=2 [23 02]

You should actually be seeing more DKEEP messages now, but the server just stops. I connected with telnet to 127.0.0.1 5551:

tom@amarok:~/projects/PIC/CANUSB4-ISO$ telnet 127.0.0.1 5551
Trying 127.0.0.1…
Connected to 127.0.0.1.
Escape character is ‘^]’.

After some restarts I wait a while and see the DKEEP messages with CANUSB4 and some testing with CANCAB2:

2026-04-10 19:11:03.592850 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:11:07.786591 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:11:08.785321 cbus_1 D2002: RX: DSPD session=2 speed=2 direction=fwd [47 02 82]
2026-04-10 19:11:08.906860 cbus_1 D2002: RX: DSPD session=2 speed=5 direction=fwd [47 02 85]
2026-04-10 19:11:09.072714 cbus_1 D2002: RX: DSPD session=2 speed=7 direction=fwd [47 02 87]
2026-04-10 19:11:09.648790 cbus_1 D2002: RX: DSPD session=2 speed=6 direction=fwd [47 02 86]
2026-04-10 19:11:10.692923 cbus_1 D2002: RX: DSPD session=2 speed=0 direction=fwd [47 02 80]
2026-04-10 19:11:11.980309 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:11:12.035339 cbus_1 D2002: RX: DSPD session=2 speed=0 direction=fwd [47 02 80]
2026-04-10 19:11:16.173983 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:11:20.367640 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:11:24.561477 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:11:28.755092 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:11:32.948771 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:11:37.142476 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:11:41.336113 cbus_1 D2002: RX: DKEEP session=2 [23 02]

But it’s not stable; on the next start I get a stop again: 

026-04-10 19:15:00.204118 world N1012: Communication: enabled
2026-04-10 19:15:00.204693 cbus_1 D2001: TX: QNN [0D]
2026-04-10 19:15:00.204718 cbus_1 N2008: Hub listening at 127.0.0.1:5551
2026-04-10 19:15:00.204730 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:15:00.204739 cbus_1 D2002: RX: DKEEP session=2 [23 02]
2026-04-10 19:15:00.204750 cbus_1 D2002: RX: DKEEP session=2 [23 02]

I can connect with telnet to 127.0.0.1 5551, but there are no messages:

tom@amarok:~/projects/PIC/CANUSB4-ISO$ telnet 127.0.0.1 5551
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.

Sometimes it works, sometimes it doesn’t, but with JMRI as hub it always does. I repeated the tests several times.

One thing I’ve just noticed: whenever the server stops, the 3 DKEEP commands come very quickly one after the other, as if they’re only coming from the buffer.

Greetings, Tom

122

Moin Tom,

Many thanks for the info, I had to rewrite a part of CANUSB/CANEther for Hub support, I problably broke something there, I’ll have a thorough look.

Current state summary:

  1. Telnet → Traintastic[CANEther] → JMRI → CANUSB :white_check_mark:
  2. Telnet → Traintastic[CANUSB] → CANUSB :cross_mark:

I problably broke something in the CANUSB part (which I can’t test at the moment, but soon I can :slight_smile:)

Greetings,
Reinder

123

Moin Reinder,

but don’t forget, sometimes it’s run, sometimes not. Could it be that this is a problem with asio, buffer and object generation during the startup process? Because the 3 DKEEP statements from the (USB) buffer, which are supposed to be processed even though the initialization of all objects is not yet complete?

Here another example:

2026-04-10 20:28:51.001659 server N1007: Listening at 127.0.0.1:5740
2026-04-10 20:28:54.375429 client[127.0.0.1:50898] I1003: New connection
2026-04-10 20:28:58.812733 world N1012: Communication: enabled
2026-04-10 20:28:58.813315 cbus_1 D2001: TX: QNN [0D]
2026-04-10 20:28:58.813340 cbus_1 N2008: Hub listening at 127.0.0.1:5551
2026-04-10 20:28:58.813352 cbus_1 D2002: RX: PNN node=65534 manufacturer_id=165 module_id=83 flags=0x0E [B6 FF FE A5 53 0E]
2026-04-10 20:28:58.813362 cbus_1 D2002: RX: PNN node=65535 manufacturer_id=165 module_id=9 flags=0x0A [B6 FF FF A5 09 0A]

I manual enable the communication, the server sends a QNN, before the hub is listening and after the both node messages the server stops. If I use JMRI with the hub, there is no USB buffer. Could it be that my system is to fast? (or to slow, I use a RT kernel, need it for JACK & Ardour). There are also always one or two cores nearly 100% if that happens - an infinite loop or deadlock? Just an idea …

Greetings, Tom

124

Moin Tom,

That could either be initialization or timing, there is some difference between CANUSB and CANEther, CANEther needs to connect before communication can start, opening the serial port is instant.

Did some more tests on the new fromAscii function, seems to work correctly. Do you have communication issues if you only use CANUSB and keep the Hub disabled?

Greetings,
Reinder

125

Moin Reinder,

Yes, It doesn’t matter whether the hub is activated or not.

Curious, I haven’t had an server stop situation if I start the traintastic-server with strace.

Greetings, Tom

126

Moin Tom,

Ok, that narrows it down to the CANUSB implementation :slight_smile:

Can you try to add some LOG_DEBUG’s and run it in debug mode, maybe that will give an insight :slight_smile:

I can imagine that strace has an impact on the overall timing, that may surpress the issue, I usually run a debug build which has that too.

Greetings,
Reinder

127

Hi Reinder,

how I start it in debug mode?

Greetings, Tom

128

Moin Tom,

You need to build it for debugging mode using CMake:

Common practice is to create a build folder in the server folder, and in that folder do:

  • configure: cmake ../ -DCMAKE_BUILD_TYPE=Debug
  • build: cmake --build . --config Debug --target traintastic-server -j 8

-j 8 is number of cores to use.

Greetings,
Reinder

129

Moin Reinder,

okay, thanks.

I have change a setting: go online when loaded. I startet the server over 20 times and no problems.

I think the problem is a minimal timing issue at startup. Could we add for testing a timer after init the /dev/ACM0 device and flush the buffer?

Greetings, Tom

130

Moin Tom,

When an interface goes online Traintastic’s buffers are all empty. The CANUSB buffer might contain messages, or a partly message. Traintastic can handle that, you’ll see a W2001 Received malformd data, dropped X bytes message in the log. The messages start with a : so it will discard all bytes received until a : is received.

Can you give this a try, replace CANUSBIOHandler::start() by:

void CANUSBIOHandler::start()
{
  boost::asio::post(m_kernel.ioContext(),
    [this]()
    {
      read();
      m_kernel.started();
    });
}

Greetings,
Reinder

131

Moin Reinder,

I compiled with Debug Mode, but that changes nothing.

I have release the loco by CANCAB2, so there comes no message (DKEEP) at startup, the server starts up without problems.

I enabled again the current event every 5s from CANCMDB. I have disabeled it in the afternoon. I add a LOG_DEBUG in cbuskernel.cpp

 m_ioHandler->onReceive =
          [this](const CAN::Message& canMessage)
          {
            LOG_DEBUG("onReceive->canMessage");
            receive(canMessage);
            if(m_hub)
            {
              m_hub->send(canMessage);
            }
          };

        m_ioHandler->start();

Have a look at that:

026-04-10 23:15:47.271832 world N1012: Communication: enabled
2026-04-10 23:15:47.272359  D0000: onReceive->canMessage
2026-04-10 23:15:47.272431  D0000: onReceive->canMessage
2026-04-10 23:15:47.272451 cbus_1 D2001: TX: QNN [0D]
2026-04-10 23:15:47.272478 cbus_1 N2008: Hub listening at 127.0.0.1:5551
2026-04-10 23:15:47.272492 cbus_1 D2002: RX: ACON2 node=65534 event=1 data=0 0 (0) [D0 FF FE 00 01 00 00]
2026-04-10 23:15:47.272504 cbus_1 D2002: RX: ACON2 node=65534 event=1 data=0 0 (0) [D0 FF FE 00 01 00 00]

There are two events from CANCMDB, the info about the current. The time could not be correct, because these event is only send every 5s.

This is absolutly curious: I stop the server, disconnect the CANCMDB and CANUSB4 and only connect CANUSB4 again, then start the server:

2026-04-10 23:23:54.235882 world N1012: Communication: enabled
2026-04-10 23:23:54.513780  D0000: onReceive->canMessage
2026-04-10 23:23:54.513824 cbus_1 D2001: TX: QNN [0D]
2026-04-10 23:23:54.513855 cbus_1 N2008: Hub listening at 127.0.0.1:5551
2026-04-10 23:23:54.513868 cbus_1 D2002: RX: ACON2 node=65534 event=1 data=0 0 (0) [D0 FF FE 00 01 00 00]

This message could be never come on time from CANCMDB, it’s not connected.

I stop and start the server again:

2026-04-10 23:26:15.211234 world N1012: Communication: enabled
2026-04-10 23:26:15.212070 cbus_1 D2001: TX: QNN [0D]
2026-04-10 23:26:15.212100 cbus_1 N2008: Hub listening at 127.0.0.1:5551
2026-04-10 23:26:15.214422  D0000: onReceive->canMessage
2026-04-10 23:26:15.214479 cbus_1 D2002: RX: PNN node=2 manufacturer_id=165 module_id=32 flags=0x5F [B6 00 02 A5 20 5F]
2026-04-10 23:26:15.464590 cbus_1 D2001: TX: RQNPN node=2 param=7 [73 00 02 07]
2026-04-10 23:26:15.467373  D0000: onReceive->canMessage
2026-04-10 23:26:15.467436 cbus_1 D2002: RX: PARAN node=2 param=7 value=4 [9B 00 02 07 04]
2026-04-10 23:26:15.467461 cbus_1 D2001: TX: RQNPN node=2 param=2 [73 00 02 02]
2026-04-10 23:26:15.470149  D0000: onReceive->canMessage
2026-04-10 23:26:15.470215 cbus_1 D2002: RX: PARAN node=2 param=2 value=100 [9B 00 02 02 64]
2026-04-10 23:26:15.470239 cbus_1 D2001: TX: RQNPN node=2 param=20 [73 00 02 14]
2026-04-10 23:26:15.472993  D0000: onReceive->canMessage
2026-04-10 23:26:15.473058 cbus_1 D2002: RX: PARAN node=2 param=20 value=7 [9B 00 02 14 07]
2026-04-10 23:26:15.473081 cbus_1 D2001: TX: RSTAT [0C]
2026-04-10 23:27:10.494663  D0000: onReceive->canMessage
2026-04-10 23:27:10.494745 cbus_1 D2002: RX: ACON node=1 event=11 [90 00 01 00 0B]
2026-04-10 23:27:10.674740  D0000: onReceive->canMessage
2026-04-10 23:27:10.674798 cbus_1 D2002: RX: ACOF node=1 event=11 [91 00 01 00 0B]
2026-04-10 23:27:15.256282  D0000: onReceive->canMessage
2026-04-10 23:27:15.256347 cbus_1 D2002: RX: ACON node=1 event=13 [90 00 01 00 0D]
2026-04-10 23:27:15.487213  D0000: onReceive->canMessage
2026-04-10 23:27:15.487293 cbus_1 D2002: RX: ACOF node=1 event=13 [91 00 01 00 0D]

It runs and the events are all correct from CANMIO.

I stop the server again and press the input keys of CANMIO, then I start the server again and it hungs:

2026-04-10 23:28:23.528471 world N1012: Communication: enabled
2026-04-10 23:28:23.529060  D0000: onReceive->canMessage
2026-04-10 23:28:23.529086 cbus_1 D2001: TX: QNN [0D]
2026-04-10 23:28:23.529110  D0000: onReceive->canMessage
2026-04-10 23:28:23.529112 cbus_1 N2008: Hub listening at 127.0.0.1:5551
2026-04-10 23:28:23.529128 cbus_1 D2002: RX: ACON node=1 event=1234 [90 00 01 04 D2]
2026-04-10 23:28:23.529151 cbus_1 D2002: RX: ACOF node=1 event=1234 [91 00 01 04 D2]

I think that narrows down the problem considerably; whenever there is data in the buffer of CANUSB4 or the USB device when starting the server, the problem occurs. That would also explain the sporadic working at startup; if it starts at the right moment, there is no problem.

Greetings, Tom

132

Reinder, I will try it tomorrow, time to power off :yawning_face: Good night, Tom :zzz:

133

Moin Tom,

You did an awesome job tracing it down.

Yeah, I agree, now I wonder if this also occurs with the “old” implementation before the hub was added.

I think it is easiest to make another clone of Traintastic in a separate folder and build it:
git clone https://github.com/traintastic/traintastic.git 709b2d1437d3b2246e9a9e9cb7f390ec4cb3d849 traintastic-before-cbus-hub

But that is something for another day, sleep well :zzz:

Greetings,
Reinder

134

Good morning Tom,

I think I found the bug!, see commit c248d20f.

Now I can sleep :zzz:

Greetings,
Reinder