From b63adbb6018744f8bcf0427c68edd5cd72cd347f Mon Sep 17 00:00:00 2001 From: Icedsoda <29167146+1cedsoda@users.noreply.github.com> Date: Sun, 1 Jun 2025 13:19:50 +0200 Subject: [PATCH] use `tracing` crate instead of `log` remove module path from logs setup tracing subscriber --- Cargo.lock | 399 +++++++++++++++--- control-core/Cargo.toml | 2 +- .../actors/mitsubishi_inverter_rs485/mod.rs | 4 +- .../src/ethercat/eeprom_identification.rs | 50 ++- .../src/ethercat/interface_discovery.rs | 12 +- control-core/src/helpers/hashing.rs | 2 +- control-core/src/machines/identification.rs | 12 + control-core/src/machines/manager.rs | 16 +- control-core/src/serial/serial_detection.rs | 19 +- control-core/src/socketio/namespace.rs | 9 +- control-core/src/socketio/socket_queue.rs | 104 +++-- server/Cargo.toml | 10 +- server/src/ethercat/init.rs | 4 +- server/src/ethercat/setup.rs | 8 +- server/src/init_tracing.rs | 44 ++ server/src/loop.rs | 2 +- server/src/machines/dre/api.rs | 6 +- server/src/machines/extruder1/api.rs | 6 +- server/src/machines/mock/api.rs | 6 +- server/src/machines/winder2/api.rs | 6 +- server/src/machines/winder2/new.rs | 7 - server/src/main.rs | 34 +- server/src/mock/init.rs | 22 +- server/src/rest/handlers/machine_mutation.rs | 9 + server/src/rest/init.rs | 35 +- server/src/rest/util.rs | 6 +- server/src/serial/init.rs | 1 - server/src/socketio/init.rs | 116 +++-- server/src/socketio/main_namespace/mod.rs | 6 +- 29 files changed, 653 insertions(+), 304 deletions(-) create mode 100644 server/src/init_tracing.rs diff --git a/Cargo.lock b/Cargo.lock index 7967aeb9..4b589dcc 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -26,6 +26,21 @@ dependencies = [ "memchr", ] +[[package]] +name = "android-tzdata" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e999941b234f3131b00bc13c22d06e8c5ff726d1b6318ac7eb276997bbb4fef0" + +[[package]] +name = "android_system_properties" +version = "0.1.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "819e7219dbd41043ac279b19830f2efc897156490d7fd6ea916720117ee66311" +dependencies = [ + "libc", +] + [[package]] name = "anes" version = "0.1.6" @@ -389,6 +404,12 @@ dependencies = [ "piper", ] +[[package]] +name = "bumpalo" +version = "3.17.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1628fb46dfa0b37568d12e5edd512553eccf6a22a78e8bde00bb4aed84d5bdbf" + [[package]] name = "byteorder" version = "1.5.0" @@ -431,6 +452,18 @@ version = "0.2.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "613afe47fcd5fac7ccf1db93babcb082c5994d996f20b8b159f2ad1658eb5724" +[[package]] +name = "chrono" +version = "0.4.41" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c469d952047f47f91b68d1cba3f10d63c11d73e4636f24f08daf0278abf01c4d" +dependencies = [ + "android-tzdata", + "iana-time-zone", + "num-traits", + "windows-link", +] + [[package]] name = "ciborium" version = "0.2.2" @@ -525,13 +558,13 @@ dependencies = [ "ethercat_hal", "ethercrab", "interfaces", - "log", "serde", "serde_json", "serial", "serialport", "smol", "socketioxide", + "tracing", "uom", ] @@ -840,29 +873,6 @@ dependencies = [ "serde", ] -[[package]] -name = "env_filter" -version = "0.1.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "186e05a59d4c50738528153b83b0b0194d3a29507dfec16eccd4b342903397d0" -dependencies = [ - "log", - "regex", -] - -[[package]] -name = "env_logger" -version = "0.11.8" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "13c863f0904021b108aa8b2f55046443e6b1ebde8fd4a15c399893aae4fa069f" -dependencies = [ - "anstream", - "anstyle", - "env_filter", - "jiff", - "log", -] - [[package]] name = "equivalent" version = "1.0.2" @@ -1328,6 +1338,30 @@ dependencies = [ "tower-service", ] +[[package]] +name = "iana-time-zone" +version = "0.1.63" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b0c919e5debc312ad217002b8048a17b7d83f80703865bbfcfebb0458b0b27d8" +dependencies = [ + "android_system_properties", + "core-foundation-sys", + "iana-time-zone-haiku", + "js-sys", + "log", + "wasm-bindgen", + "windows-core", +] + +[[package]] +name = "iana-time-zone-haiku" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f31827a206f56af32e590ba56d5d2d085f558508192593743f16b2306495269f" +dependencies = [ + "cc", +] + [[package]] name = "if_chain" version = "1.0.2" @@ -1451,27 +1485,13 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4a5f13b858c8d314ee3e8f639011f7ccefe71f97f96e50151fb991f267928e2c" [[package]] -name = "jiff" -version = "0.2.12" +name = "js-sys" +version = "0.3.77" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d07d8d955d798e7a4d6f9c58cd1f1916e790b42b092758a9ef6e16fef9f1b3fd" +checksum = "1cfaf33c695fc6e08064efbc1f72ec937429614f25eef83af942d0e227c3a28f" dependencies = [ - "jiff-static", - "log", - "portable-atomic", - "portable-atomic-util", - "serde", -] - -[[package]] -name = "jiff-static" -version = "0.2.12" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "f244cfe006d98d26f859c7abd1318d85327e1882dc9cef80f62daeeb0adcf300" -dependencies = [ - "proc-macro2", - "quote", - "syn 2.0.101", + "once_cell", + "wasm-bindgen", ] [[package]] @@ -1553,6 +1573,15 @@ dependencies = [ "libc", ] +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata 0.1.10", +] + [[package]] name = "matchit" version = "0.8.4" @@ -1672,6 +1701,16 @@ version = "0.6.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "43794a0ace135be66a25d3ae77d41b91615fb68ae937f904090203e81f755b65" +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + [[package]] name = "num-traits" version = "0.2.19" @@ -1713,6 +1752,12 @@ dependencies = [ "pathdiff", ] +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "parking" version = "2.2.1" @@ -1814,6 +1859,26 @@ dependencies = [ "sha2", ] +[[package]] +name = "pin-project" +version = "1.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "677f1add503faace112b9f1373e43e9e054bfdd22ff1a63c1bc485eaec6a6a8a" +dependencies = [ + "pin-project-internal", +] + +[[package]] +name = "pin-project-internal" +version = "1.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6e918e4ff8c4549eb882f14b3a4bc8c8bc93de829416eacf579f1207a8fbf861" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.101", +] + [[package]] name = "pin-project-lite" version = "0.2.16" @@ -1890,21 +1955,6 @@ dependencies = [ "windows-sys 0.59.0", ] -[[package]] -name = "portable-atomic" -version = "1.11.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "350e9b48cbc6b0e028b0473b114454c6316e57336ee184ceab6e53f72c178b3e" - -[[package]] -name = "portable-atomic-util" -version = "0.2.4" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d8a2f0d8d040d7848a709caf78912debcc3f33ee4b3cac47d73d1e1069e83507" -dependencies = [ - "portable-atomic", -] - [[package]] name = "ppv-lite86" version = "0.2.21" @@ -2006,8 +2056,17 @@ checksum = "b544ef1b4eac5dc2db33ea63606ae9ffcfac26c1416a2806ae0bf5f56b201191" dependencies = [ "aho-corasick", "memchr", - "regex-automata", - "regex-syntax", + "regex-automata 0.4.9", + "regex-syntax 0.8.5", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax 0.6.29", ] [[package]] @@ -2018,9 +2077,15 @@ checksum = "809e8dc61f6de73b46c85f4c96486310fe304c434cfa43669d7b40f711150908" dependencies = [ "aho-corasick", "memchr", - "regex-syntax", + "regex-syntax 0.8.5", ] +[[package]] +name = "regex-syntax" +version = "0.6.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1" + [[package]] name = "regex-syntax" version = "0.8.5" @@ -2216,11 +2281,9 @@ dependencies = [ "control_core", "crc", "dhat", - "env_logger", "ethercat_hal", "ethercrab", "lazy_static", - "log", "open", "serde", "serde_json", @@ -2232,6 +2295,10 @@ dependencies = [ "tikv-jemallocator", "tokio", "tower-http", + "tracing", + "tracing-futures", + "tracing-journald", + "tracing-subscriber", "uom", ] @@ -2257,6 +2324,15 @@ dependencies = [ "digest", ] +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "1.3.0" @@ -2503,6 +2579,16 @@ dependencies = [ "winapi", ] +[[package]] +name = "thread_local" +version = "1.1.8" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8b9ef9bad013ada3808854ceac7b46812a6465ba368859a37e2100283d2d719c" +dependencies = [ + "cfg-if", + "once_cell", +] + [[package]] name = "tikv-jemalloc-sys" version = "0.6.0+5.3.0-1-ge13ca993e8ccb9ba9847cc330696e02839f328f7" @@ -2672,9 +2758,21 @@ checksum = "784e0ac535deb450455cbfa28a6f0df145ea1bb7ae51b821cf5e7927fdcfbdd0" dependencies = [ "log", "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-attributes" +version = "0.1.28" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "395ae124c09f9e6918a2310af6038fba074bcf474ac352496d5910dd59a2226d" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.101", +] + [[package]] name = "tracing-core" version = "0.1.33" @@ -2682,6 +2780,58 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e672c95779cf947c5311f83787af4fa8fffd12fb27e4993211a84bdfd9610f9c" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-futures" +version = "0.2.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "97d095ae15e245a057c8e8451bab9b3ee1e1f68e9ba2b4fbc18d0ac5237835f2" +dependencies = [ + "pin-project", + "tracing", +] + +[[package]] +name = "tracing-journald" +version = "0.3.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "fc0b4143302cf1022dac868d521e36e8b27691f72c84b3311750d5188ebba657" +dependencies = [ + "libc", + "tracing-core", + "tracing-subscriber", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.19" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e8189decb5ac0fa7bc8b96b7cb9b2701d60d48805aca84a238004d665fcc4008" +dependencies = [ + "chrono", + "matchers", + "nu-ansi-term", + "once_cell", + "regex", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", + "tracing-core", + "tracing-log", ] [[package]] @@ -2756,6 +2906,12 @@ version = "0.2.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "06abde3611657adf66d383f00b093d7faecc7fa57071cce2578660c9f1010821" +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" + [[package]] name = "version_check" version = "0.9.5" @@ -2793,6 +2949,64 @@ dependencies = [ "wit-bindgen-rt", ] +[[package]] +name = "wasm-bindgen" +version = "0.2.100" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1edc8929d7499fc4e8f0be2262a241556cfc54a0bea223790e71446f2aab1ef5" +dependencies = [ + "cfg-if", + "once_cell", + "rustversion", + "wasm-bindgen-macro", +] + +[[package]] +name = "wasm-bindgen-backend" +version = "0.2.100" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2f0a0651a5c2bc21487bde11ee802ccaf4c51935d0d3d42a6101f98161700bc6" +dependencies = [ + "bumpalo", + "log", + "proc-macro2", + "quote", + "syn 2.0.101", + "wasm-bindgen-shared", +] + +[[package]] +name = "wasm-bindgen-macro" +version = "0.2.100" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7fe63fc6d09ed3792bd0897b314f53de8e16568c2b3f7982f468c0bf9bd0b407" +dependencies = [ + "quote", + "wasm-bindgen-macro-support", +] + +[[package]] +name = "wasm-bindgen-macro-support" +version = "0.2.100" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8ae87ea40c9f689fc23f209965b6fb8a99ad69aeeb0231408be24920604395de" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.101", + "wasm-bindgen-backend", + "wasm-bindgen-shared", +] + +[[package]] +name = "wasm-bindgen-shared" +version = "0.2.100" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1a05d73b933a847d6cccdda8f838a22ff101ad9bf93e33684f39c1f5f0eece3d" +dependencies = [ + "unicode-ident", +] + [[package]] name = "winapi" version = "0.3.9" @@ -2824,6 +3038,65 @@ version = "0.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "712e227841d057c1ee1cd2fb22fa7e5a5461ae8e48fa2ca79ec42cfc1931183f" +[[package]] +name = "windows-core" +version = "0.61.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "4763c1de310c86d75a878046489e2e5ba02c649d185f21c67d4cf8a56d098980" +dependencies = [ + "windows-implement", + "windows-interface", + "windows-link", + "windows-result", + "windows-strings", +] + +[[package]] +name = "windows-implement" +version = "0.60.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a47fddd13af08290e67f4acabf4b459f647552718f683a7b415d290ac744a836" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.101", +] + +[[package]] +name = "windows-interface" +version = "0.59.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bd9211b69f8dcdfa817bfd14bf1c97c9188afa36f4750130fcdf3f400eca9fa8" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.101", +] + +[[package]] +name = "windows-link" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "76840935b766e1b0a05c0066835fb9ec80071d4c09a16f6bd5f7e655e3c14c38" + +[[package]] +name = "windows-result" +version = "0.3.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c64fd11a4fd95df68efcfee5f44a294fe71b8bc6a91993e2791938abcc712252" +dependencies = [ + "windows-link", +] + +[[package]] +name = "windows-strings" +version = "0.4.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7a2ba9642430ee452d5a7aa78d72907ebe8cfda358e8cb7918a2050581322f97" +dependencies = [ + "windows-link", +] + [[package]] name = "windows-sys" version = "0.36.1" diff --git a/control-core/Cargo.toml b/control-core/Cargo.toml index 90a0b596..efc08be7 100644 --- a/control-core/Cargo.toml +++ b/control-core/Cargo.toml @@ -9,7 +9,6 @@ axum = "0.8.4" ethercat_hal = { path = "../ethercat-hal" } ethercrab = "0.6" interfaces = "0.0.9" -log = "0.4.27" serde = "1.0.219" serde_json = "1.0.140" serialport = "4.7.1" @@ -19,5 +18,6 @@ uom = "0.36.0" bitvec = { version = "1.0.1", features = ["alloc"] } crc = "3.2.1" serial = "0.4.0" +tracing = "0.1.41" [dev-dependencies] approx = "0.5.1" diff --git a/control-core/src/actors/mitsubishi_inverter_rs485/mod.rs b/control-core/src/actors/mitsubishi_inverter_rs485/mod.rs index 10f30127..3899841c 100644 --- a/control-core/src/actors/mitsubishi_inverter_rs485/mod.rs +++ b/control-core/src/actors/mitsubishi_inverter_rs485/mod.rs @@ -359,7 +359,7 @@ impl MitsubishiInverterRS485Actor { Ok(result) } Err(_) => { - log::error!("Error Parsing ModbusResponse!"); + tracing::error!("Error Parsing ModbusResponse!"); self.state = State::ReadyToSend; Err(anyhow::anyhow!("error")) } @@ -380,7 +380,7 @@ impl MitsubishiInverterRS485Actor { let res = (self.serial_interface.write_message)(modbus_request.clone()).await; match res { Ok(_) => (), - Err(_) => log::error!("ERROR: serial_interface.write_message has failed"), + Err(_) => tracing::error!("ERROR: serial_interface.write_message has failed"), } self.state = State::WaitingForRequestAccept; self.last_message_size = modbus_request.len(); diff --git a/control-core/src/ethercat/eeprom_identification.rs b/control-core/src/ethercat/eeprom_identification.rs index cb00ecaf..84095120 100644 --- a/control-core/src/ethercat/eeprom_identification.rs +++ b/control-core/src/ethercat/eeprom_identification.rs @@ -25,8 +25,7 @@ use ethercat_hal::devices::el7031_0030::EL7031_0030_IDENTITY_A; use ethercat_hal::devices::el7041_0052::EL7041_0052_IDENTITY_A; use ethercat_hal::devices::subdevice_identity_to_tuple; use ethercat_hal::helpers::ethercrab_types::{ - EthercrabSubDeviceOperational, - EthercrabSubDevicePreoperational, + EthercrabSubDeviceOperational, EthercrabSubDevicePreoperational, }; use ethercrab::MainDevice; use ethercrab::SubDeviceIdentity; @@ -68,9 +67,7 @@ impl Default for MachineIdentificationAddresses { /// Reads the EEPROM of all subdevices to get their machine device identifications /// /// Returns a vector of MachineDeviceIdentification for all subdevices -pub async fn read_device_identifications< - 'maindevice, ->( +pub async fn read_device_identifications<'maindevice>( subdevices: &Vec>, maindevice: &MainDevice<'maindevice>, ) -> Vec> { @@ -123,7 +120,6 @@ pub async fn machine_device_identification<'maindevice>( module_path!(), subdevice.name() )))?, - }, role: subdevice .eeprom_read::(maindevice, addresses.role_word) @@ -135,17 +131,20 @@ pub async fn machine_device_identification<'maindevice>( )))?, }; - log::debug!( - "[{}::machine_device_identification] Read MDI from EEPROM for device {}\nVendor: 0x{:08x} at 0x{:04x}-0x{:04x}\nSerial: 0x{:08x} at 0x{:04x}-0x{:04x}\nMachine: 0x{:08x} at 0x{:04x}-0x{:04x}\nRole: 0x{:08x} at 0x{:04x}-0x{:04x}", - module_path!(), + tracing::debug!( + "Read MDI from EEPROM for device {}\nVendor: 0x{:08x} at 0x{:04x}-0x{:04x}\nSerial: 0x{:08x} at 0x{:04x}-0x{:04x}\nMachine: 0x{:08x} at 0x{:04x}-0x{:04x}\nRole: 0x{:08x} at 0x{:04x}-0x{:04x}", subdevice.name(), - mdi.machine_identification_unique.machine_identification.vendor, + mdi.machine_identification_unique + .machine_identification + .vendor, addresses.vendor_word, addresses.vendor_word + 1, mdi.machine_identification_unique.serial, addresses.serial_word, addresses.serial_word + 1, - mdi.machine_identification_unique.machine_identification.machine, + mdi.machine_identification_unique + .machine_identification + .machine, addresses.machine_word, addresses.machine_word + 1, mdi.role, @@ -163,17 +162,22 @@ pub async fn write_machine_device_identification<'maindevice, const MAX_PDI: usi device_identification: &DeviceMachineIdentification, ) -> Result<(), Error> { let addresses = get_identification_addresses(&subdevice.identity(), subdevice.name())?; - log::debug!( - "[{}::write_machine_device_identification] Writing MDI to EEPROM for device {}\nVendor: 0x{:08x} at 0x{:04x}-0x{:04x}\nSerial: 0x{:08x} at 0x{:04x}-0x{:04x}\nMachine: 0x{:08x} at 0x{:04x}-0x{:04x}\nRole: 0x{:08x} at 0x{:04x}-0x{:04x}", - module_path!(), + tracing::debug!( + "Writing MDI to EEPROM for device {}\nVendor: 0x{:08x} at 0x{:04x}-0x{:04x}\nSerial: 0x{:08x} at 0x{:04x}-0x{:04x}\nMachine: 0x{:08x} at 0x{:04x}-0x{:04x}\nRole: 0x{:08x} at 0x{:04x}-0x{:04x}", subdevice.name(), - device_identification.machine_identification_unique.machine_identification.vendor, + device_identification + .machine_identification_unique + .machine_identification + .vendor, addresses.vendor_word, addresses.vendor_word + 1, device_identification.machine_identification_unique.serial, addresses.serial_word, addresses.serial_word + 1, - device_identification.machine_identification_unique.machine_identification.machine, + device_identification + .machine_identification_unique + .machine_identification + .machine, addresses.machine_word, addresses.machine_word + 1, device_identification.role, @@ -185,7 +189,10 @@ pub async fn write_machine_device_identification<'maindevice, const MAX_PDI: usi .eeprom_write_dangerously( maindevice, addresses.vendor_word, - device_identification.machine_identification_unique.machine_identification.vendor, + device_identification + .machine_identification_unique + .machine_identification + .vendor, ) .await?; subdevice @@ -199,7 +206,10 @@ pub async fn write_machine_device_identification<'maindevice, const MAX_PDI: usi .eeprom_write_dangerously( maindevice, addresses.machine_word, - device_identification.machine_identification_unique.machine_identification.machine, + device_identification + .machine_identification_unique + .machine_identification + .machine, ) .await?; subdevice @@ -234,7 +244,9 @@ pub fn get_identification_addresses<'maindevice>( EL7031_IDENTITY_A | EL7031_IDENTITY_B => MachineIdentificationAddresses::default(), EL7031_0030_IDENTITY_A => MachineIdentificationAddresses::default(), EL7041_0052_IDENTITY_A => MachineIdentificationAddresses::default(), - EL6021_IDENTITY_A | EL6021_IDENTITY_B | EL6021_IDENTITY_C => MachineIdentificationAddresses::default(), + EL6021_IDENTITY_A | EL6021_IDENTITY_B | EL6021_IDENTITY_C => { + MachineIdentificationAddresses::default() + } _ => { // block_on(u16dump(&subdevice, maindevice, 0x00, 0xff))?; Err(anyhow!( diff --git a/control-core/src/ethercat/interface_discovery.rs b/control-core/src/ethercat/interface_discovery.rs index aa4e7348..08d1d816 100644 --- a/control-core/src/ethercat/interface_discovery.rs +++ b/control-core/src/ethercat/interface_discovery.rs @@ -21,21 +21,21 @@ const IFACE_DISCOVERY_MAX_PDI_LEN: usize = 128; /// } /// ``` pub async fn discover_ethercat_interface() -> Result { - log::info!("Discovering EtherCAT interface..."); + tracing::info!("Discovering EtherCAT interface..."); // Set up a custom panic hook that suppresses panic output let default_hook = std::panic::take_hook(); std::panic::set_hook(Box::new(move |panic_info| { // Optional: log the panic in a controlled way if let Some(location) = panic_info.location() { - log::debug!( + tracing::debug!( "Suppressed panic in interface test: {} (at {}:{})", panic_info, location.file(), location.line() ); } else { - log::debug!("Suppressed panic in interface test: {}", panic_info); + tracing::debug!("Suppressed panic in interface test: {}", panic_info); } // Don't call the default hook, which would print the backtrace })); @@ -65,11 +65,11 @@ pub async fn discover_ethercat_interface() -> Result { smol::block_on(async { match test_interface(&name) { Ok(_) => { - log::debug!("Found working EtherCAT interface: {}", name); + tracing::info!("Found working EtherCAT interface: {}", name); Some(name.clone()) } Err(e) => { - log::debug!("Interface {} failed: {}", name, e); + tracing::debug!("Interface {} failed: {}", name, e); None } } @@ -99,7 +99,7 @@ pub async fn discover_ethercat_interface() -> Result { } fn test_interface(interface: &str) -> Result<(), anyhow::Error> { - log::debug!("Testing interface: {}", interface); + tracing::trace!("Testing interface: {}", interface); let pdu_storage = Box::leak(Box::new(PduStorage::< IFACE_DISCOVERY_MAX_FRAMES, diff --git a/control-core/src/helpers/hashing.rs b/control-core/src/helpers/hashing.rs index 11979c42..e28e9755 100644 --- a/control-core/src/helpers/hashing.rs +++ b/control-core/src/helpers/hashing.rs @@ -32,7 +32,7 @@ fn test_hash() { let test_case = "/dev/ttyUSB1"; let hash = hashing(test_case); let hash_2bytes = xor_u128_to_u16(hash); - log::info!("{}", test_case); + tracing::info!("{}", test_case); assert_eq!(test_case, "/dev/ttyUSB1"); assert!(hash == 8977446972540388683742); assert!(hash_2bytes == 165); diff --git a/control-core/src/machines/identification.rs b/control-core/src/machines/identification.rs index 7bd1120b..b78a4763 100644 --- a/control-core/src/machines/identification.rs +++ b/control-core/src/machines/identification.rs @@ -1,3 +1,5 @@ +use std::fmt::Display; + use serde::Deserialize; use serde::Serialize; @@ -15,6 +17,16 @@ impl MachineIdentificationUnique { } } +impl Display for MachineIdentificationUnique { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!( + f, + "{}/{}/{}", + self.machine_identification.vendor, self.machine_identification.machine, self.serial + ) + } +} + /// Identifies a machine #[derive(Debug, Clone, Serialize, Deserialize, PartialEq, Eq, Hash)] pub struct MachineIdentification { diff --git a/control-core/src/machines/manager.rs b/control-core/src/machines/manager.rs index 4ed3049a..9098de8e 100644 --- a/control-core/src/machines/manager.rs +++ b/control-core/src/machines/manager.rs @@ -43,9 +43,8 @@ impl MachineManager { // group devices by machine device identification let device_grouping_result = group_devices_by_identification(device_identifications); - log::info!( - "[{}::set_ethercat_devices] Device Groups {:?}", - module_path!(), + tracing::info!( + "Device Groups {:?}", device_grouping_result.device_groups.len() ); @@ -101,11 +100,7 @@ impl MachineManager { hardware: &MachineNewHardware::Serial(&hardware), }); - log::info!( - "[{}::add_serial_device] Adding serial machine {:?}", - module_path!(), - new_machine - ); + tracing::info!("Adding serial machine {:?}", new_machine); self.serial_machines.insert( device_identification_identified @@ -122,6 +117,11 @@ impl MachineManager { .try_into() .expect("Serial devices always have machine identification"); + tracing::info!( + "Removing serial machine {:?}", + device_identification_identified + ); + self.serial_machines.remove( &device_identification_identified .device_machine_identification diff --git a/control-core/src/serial/serial_detection.rs b/control-core/src/serial/serial_detection.rs index 75befcca..c1d9e17b 100644 --- a/control-core/src/serial/serial_detection.rs +++ b/control-core/src/serial/serial_detection.rs @@ -115,11 +115,7 @@ impl<'serialdeviceregistry> SerialDetection<'serialdeviceregistry> { result.removed.push(device_identification); } - log::info!( - "[{}::SerialDetection::check_ports] Removed port: {}", - module_path!(), - removed.0 - ); + tracing::trace!("Removed port: {}", removed.0); } // add new ports @@ -153,11 +149,7 @@ impl<'serialdeviceregistry> SerialDetection<'serialdeviceregistry> { // add to result list result.added.push((device_identification, device.clone())); - log::debug!( - "[{}::SerialDetection::check_ports] Added port: {}", - module_path!(), - added.0 - ); + tracing::trace!("Added port: {}", added.0); } } @@ -174,12 +166,7 @@ impl<'serialdeviceregistry> SerialDetection<'serialdeviceregistry> { }; self.ports.remove(&path); - log::debug!( - "[{}::SerialDetection::check_remove_signals] Removed device: {:?}: {}", - module_path!(), - path, - error - ); + tracing::trace!("Removed device: {:?}: {}", path, error); } Err(_) => {} } diff --git a/control-core/src/socketio/namespace.rs b/control-core/src/socketio/namespace.rs index b4ed361d..01edd912 100644 --- a/control-core/src/socketio/namespace.rs +++ b/control-core/src/socketio/namespace.rs @@ -1,6 +1,7 @@ use crate::socketio::event::GenericEvent; use socketioxide::{extract::SocketRef, socket::Sid}; use std::{collections::HashMap, time::Duration}; +use tracing::instrument; use super::socket_queue::SocketQueue; @@ -84,6 +85,7 @@ impl Namespace { } impl NamespaceInterface for Namespace { + #[instrument] fn subscribe(&mut self, socket: SocketRef) { // add the socket to the list self.sockets.push(socket.clone()); @@ -91,6 +93,7 @@ impl NamespaceInterface for Namespace { self.socket_queues.insert(socket.id, SocketQueue::new()); } + #[instrument] fn unsubscribe(&mut self, socket: SocketRef) { // remove the socket from the list self.sockets.retain(|s| s.id != socket.id); @@ -98,6 +101,7 @@ impl NamespaceInterface for Namespace { self.socket_queues.remove(&socket.id); } + #[instrument] fn reemit(&mut self, socket: SocketRef) { if let Some(queue) = self.socket_queues.get(&socket.id) { // Collect events grouped by name/kind with their counts for sorting @@ -112,11 +116,12 @@ impl NamespaceInterface for Namespace { queue.push(event.clone()); } } - + queue.flush(socket.clone()); } } + #[instrument] fn emit(&mut self, event: &GenericEvent) { // Use the new emit function which combines push and flush for socket in self.sockets.clone() { @@ -127,6 +132,7 @@ impl NamespaceInterface for Namespace { } } + #[instrument(skip(buffer_fn))] fn cache( &mut self, event: &GenericEvent, @@ -139,6 +145,7 @@ impl NamespaceInterface for Namespace { buffer_fn(&mut cached_events_for_key, event); } + #[instrument(skip(buffer_fn))] fn emit_cached( &mut self, event: &GenericEvent, diff --git a/control-core/src/socketio/socket_queue.rs b/control-core/src/socketio/socket_queue.rs index 137e2d50..e41900d9 100644 --- a/control-core/src/socketio/socket_queue.rs +++ b/control-core/src/socketio/socket_queue.rs @@ -8,6 +8,7 @@ use std::{ }; use socketioxide::extract::SocketRef; +use tracing::{Instrument, debug_span, instrument}; use super::event::GenericEvent; @@ -28,6 +29,7 @@ impl SocketQueue { } /// Add an event to the queue + #[instrument] pub fn push(&self, event: GenericEvent) { if let Ok(mut queue) = self.queue.lock() { queue.push_back(event); @@ -35,6 +37,7 @@ impl SocketQueue { } /// Force flush events asynchronously (assumes flushing flag is already set) + #[instrument(skip_all)] pub fn flush(&self, socket: SocketRef) { // Check if we're already flushing if self @@ -49,59 +52,72 @@ impl SocketQueue { let queue = Arc::clone(&self.queue); let is_flushing = Arc::clone(&self.is_flushing); + let span = debug_span!("socket_queue_flush", socket_id = ?socket.id); + // Spawn a smol task to flush the queue - smol::spawn(async move { - // Process events directly from the queue without collecting first - loop { - let event = { - if let Ok(mut queue_guard) = queue.lock() { - queue_guard.pop_front() - } else { - break; // Exit if we can't lock the queue - } - }; - - let Some(event) = event else { - break; // No more events in queue - }; - - // retry loop for each event + smol::spawn( + async move { + // Process events directly from the queue without collecting first loop { - // check if socket is still connected - if !socket.connected() { - break; // Exit the loop if the socket is not connected - } + let event = { + if let Ok(mut queue_guard) = queue.lock() { + queue_guard.pop_front() + } else { + break; // Exit if we can't lock the queue + } + }; - match socket.emit("event", &event) { - Ok(_) => break, // Successfully emitted, exit loop - Err(e) => match e { - socketioxide::SendError::Serialize(_) => { - // no reason in retrying serialization errors - break; - } - socketioxide::SendError::Socket(socket_error) => match socket_error { - socketioxide::SocketError::InternalChannelFull => { - // wait 10ms before retrying - log::warn!( - "Socket {} internal channel full, retrying in 10ms", - socket.id, - ); - smol::Timer::after(Duration::from_millis(10)).await; - continue; // Retry sending the event - } - socketioxide::SocketError::Closed => { - // Socket is closed, no point in retrying + let Some(event) = event else { + break; // No more events in queue + }; + + // retry loop for each event + loop { + // check if socket is still connected + if !socket.connected() { + break; // Exit the loop if the socket is not connected + } + + let span = debug_span!( + "socket_queue_flush_event", + socket_id = ?socket.id, + event_name = %event.name, + ); + let _enter = span.enter(); + + match socket.emit("event", &event) { + Ok(_) => break, // Successfully emitted, exit loop + Err(e) => match e { + socketioxide::SendError::Serialize(_) => { + // no reason in retrying serialization errors break; } + socketioxide::SendError::Socket(socket_error) => match socket_error + { + socketioxide::SocketError::InternalChannelFull => { + // wait 10ms before retrying + tracing::warn!( + "Socket {} internal channel full, retrying in 10ms", + socket.id, + ); + smol::Timer::after(Duration::from_millis(10)).await; + continue; // Retry sending the event + } + socketioxide::SocketError::Closed => { + // Socket is closed, no point in retrying + break; + } + }, }, - }, + } } } - } - // Reset the flushing flag - is_flushing.store(false, Ordering::SeqCst); - }) + // Reset the flushing flag + is_flushing.store(false, Ordering::SeqCst); + } + .instrument(span), + ) .detach(); } } diff --git a/server/Cargo.toml b/server/Cargo.toml index 6566b474..7404531e 100644 --- a/server/Cargo.toml +++ b/server/Cargo.toml @@ -25,19 +25,25 @@ uom = { version = "0.36.0", default-features = false, features = ["f64"] } serde = "1.0.217" anyhow = "1.0.98" serde_json = "1.0.137" -log = "0.4.25" -env_logger = "0.11.8" tokio = { version = "1.44.2", features = ["rt-multi-thread"] } open = "5.3.2" bitvec = "1.0.1" lazy_static = "1.5.0" smol = "2.0.2" +tracing = { version = "0.1.41", features = ["attributes"] } dhat = { version = "0.3.3", optional = true } # dre usb crc = "3.2.1" serial = "0.4.0" serialport = "4.7.1" +tracing-subscriber = { version = "0.3.19", features = [ + "env-filter", + "chrono", + "registry", +] } +tracing-journald = "0.3.1" +tracing-futures = "0.2.5" [target.'cfg(not(target_env = "msvc"))'.dependencies] tikv-jemallocator = { version = "0.6", features = ["profiling"] } diff --git a/server/src/ethercat/init.rs b/server/src/ethercat/init.rs index 985271a0..187f3fb4 100644 --- a/server/src/ethercat/init.rs +++ b/server/src/ethercat/init.rs @@ -34,11 +34,11 @@ pub fn init_ethercat( loop { match discover_ethercat_interface().await { Ok(interface) => { - log::info!("Found working interface: {}", interface); + tracing::info!("Found working interface: {}", interface); break interface; } Err(_) => { - log::warn!("No working interface found, retrying..."); + tracing::warn!("No working interface found, retrying..."); // wait 1 seconds before retrying smol::Timer::after(std::time::Duration::from_secs(1)).await; } diff --git a/server/src/ethercat/setup.rs b/server/src/ethercat/setup.rs index 88373a22..3635761c 100644 --- a/server/src/ethercat/setup.rs +++ b/server/src/ethercat/setup.rs @@ -25,11 +25,11 @@ pub async fn setup_loop( interface: &str, app_state: Arc, ) -> Result<(), anyhow::Error> { - log::info!("Starting Ethercat PDU loop"); + tracing::info!("Starting Ethercat PDU loop"); // Erase all all setup data from `app_state` { - log::info!("Setting up Ethercat network"); + tracing::debug!("Setting up Ethercat network"); let mut ethercat_setup_guard = app_state.ethercat_setup.write().await; *ethercat_setup_guard = None; } @@ -98,7 +98,7 @@ pub async fn setup_loop( .await { Ok(group) => { - log::info!("Initialized {} subdevices", &group.len()); + tracing::info!("Initialized {} subdevices", &group.len()); group } Err(err) => Err(anyhow::anyhow!( @@ -205,7 +205,7 @@ pub async fn setup_loop( // Put group in operational state let group_op = match group_preop.into_op(&maindevice).await { Ok(group_op) => { - log::info!("Group in OP state"); + tracing::info!("Group in OP state"); group_op } Err(err) => Err(anyhow::anyhow!( diff --git a/server/src/init_tracing.rs b/server/src/init_tracing.rs new file mode 100644 index 00000000..8d23f47a --- /dev/null +++ b/server/src/init_tracing.rs @@ -0,0 +1,44 @@ +use tracing_subscriber::{EnvFilter, Layer, layer::SubscriberExt}; + +pub fn init_tracing() { + let registry = tracing_subscriber::registry(); + let env_filter = EnvFilter::try_from_default_env() + .unwrap_or_else(|_| EnvFilter::new("info,tower_http=debug,axum=debug")); + + // Check if QITECH_OS environment variable is set + let layer: Box + Send + Sync> = if std::env::var("QITECH_OS").is_ok() { + let journald_layer = init_journald_tracing(); + Box::new(journald_layer) + } else { + let fmt_layer = init_fmt_tracing(); + Box::new(fmt_layer) + }; + + let subscriber = registry.with(layer).with(env_filter); + + tracing::subscriber::set_global_default(subscriber).expect("Failed to set global subscriber"); +} + +fn init_journald_tracing() -> tracing_journald::Layer { + tracing_journald::layer().expect("Failed to create journald layer") +} + +fn init_fmt_tracing() -> impl Layer { + let fmt_layer = tracing_subscriber::fmt::layer() + .with_level(true) + .with_line_number(true) + .with_thread_names(true) + .with_test_writer() + .with_target(true); + + // if in debug mode, only show time not date + #[cfg(debug_assertions)] + let fmt_layer = fmt_layer.with_timer(tracing_subscriber::fmt::time::ChronoUtc::new( + "%H:%M:%S%.3f".to_string(), + )); + + #[cfg(not(debug_assertions))] + let fmt_layer = fmt_layer.with_timer(tracing_subscriber::fmt::time::ChronoUtc::rfc_3339()); + + fmt_layer +} diff --git a/server/src/loop.rs b/server/src/loop.rs index 719aeac1..b1218736 100644 --- a/server/src/loop.rs +++ b/server/src/loop.rs @@ -23,7 +23,7 @@ pub fn init_loop( loop_once(app_state.clone()).await })); if let Err(err) = res { - log::error!("Loop failed\n{:?}", err); + tracing::error!("Loop failed\n{:?}", err); break; } } diff --git a/server/src/machines/dre/api.rs b/server/src/machines/dre/api.rs index 152dd65e..3a86c6b3 100644 --- a/server/src/machines/dre/api.rs +++ b/server/src/machines/dre/api.rs @@ -84,11 +84,7 @@ impl NamespaceCacheingLogic for DreMachineNamespace { let event = match events.event_value() { Ok(event) => event, Err(err) => { - log::error!( - "[{}::emit_cached] Failed to event.event_value(): {:?}", - module_path!(), - err - ); + tracing::error!("Failed to emit: {:?}", err); return; } }; diff --git a/server/src/machines/extruder1/api.rs b/server/src/machines/extruder1/api.rs index 52e7b72f..362855a6 100644 --- a/server/src/machines/extruder1/api.rs +++ b/server/src/machines/extruder1/api.rs @@ -181,11 +181,7 @@ impl NamespaceCacheingLogic for ExtruderV2Namespace { let event = match events.event_value() { Ok(event) => event, Err(err) => { - log::error!( - "[{}::emit_cached] Failed to event.event_value(): {:?}", - module_path!(), - err - ); + tracing::error!("Failed to emit: {:?}", err); return; } }; diff --git a/server/src/machines/mock/api.rs b/server/src/machines/mock/api.rs index 29be4ab6..137f6e1b 100644 --- a/server/src/machines/mock/api.rs +++ b/server/src/machines/mock/api.rs @@ -101,11 +101,7 @@ impl NamespaceCacheingLogic for MockMachineNamespace { let event = match events.event_value() { Ok(event) => event, Err(err) => { - log::error!( - "[{}::emit_cached] Failed to event.event_value(): {:?}", - module_path!(), - err - ); + tracing::error!("Failed to emit: {:?}", err); return; } }; diff --git a/server/src/machines/winder2/api.rs b/server/src/machines/winder2/api.rs index 6ac017e0..e0d77f6f 100644 --- a/server/src/machines/winder2/api.rs +++ b/server/src/machines/winder2/api.rs @@ -287,11 +287,7 @@ impl NamespaceCacheingLogic for Winder2Namespace { let event = match events.event_value() { Ok(event) => event, Err(err) => { - log::error!( - "[{}::emit_cached] Failed to event.event_value(): {:?}", - module_path!(), - err - ); + tracing::error!("Failed to emit: {:?}", err); return; } }; diff --git a/server/src/machines/winder2/new.rs b/server/src/machines/winder2/new.rs index 90613465..816ab80c 100644 --- a/server/src/machines/winder2/new.rs +++ b/server/src/machines/winder2/new.rs @@ -69,13 +69,6 @@ impl MachineNewTrait for Winder2 { } }; - log::info!( - "[{}::MachineNewTrait/Winder2::new] Hardware: Ethercat Devices {:?}, Subdevices {:?}", - module_path!(), - hardware.ethercat_devices.len(), - hardware.subdevices.len() - ); - // using block_on because making this funciton async creates a lifetime issue // if its async the compiler thinks &subdevices is persisted in the future which might never execute // so we can't drop subdevices unless this machine is dropped, which is bad diff --git a/server/src/main.rs b/server/src/main.rs index 5fb86558..0e373b86 100644 --- a/server/src/main.rs +++ b/server/src/main.rs @@ -11,11 +11,11 @@ static ALLOC: dhat::Alloc = dhat::Alloc; use app_state::AppState; use control_core::helpers::loop_trottle::LoopThrottle; +use init_tracing::init_tracing; #[cfg(feature = "mock-machine")] use mock::init::init_mock; use std::{panic::catch_unwind, process::exit, sync::Arc, time::Duration}; -use env_logger::Env; use ethercat::init::init_ethercat; use r#loop::init_loop; use rest::init::init_api; @@ -25,6 +25,7 @@ use smol::channel::unbounded; pub mod app_state; pub mod ethercat; +pub mod init_tracing; pub mod r#loop; pub mod machines; #[cfg(feature = "mock-machine")] @@ -35,21 +36,23 @@ pub mod serial; pub mod socketio; fn main() { + init_tracing(); + tracing::info!("Tracing initialized successfully"); + // if the program panics we restart all of it match catch_unwind(|| main2()) { Ok(_) => { - log::info!("[{}::main] Program ended normally", module_path!()); + tracing::info!("Program ended normally"); exit(0); } Err(err) => { - log::error!("[{}::main] Program panicked: {:?}", module_path!(), err); + tracing::error!("Program panicked: {:?}", err); exit(1); } } } fn main2() { - env_logger::Builder::from_env(Env::default().default_filter_or("info")).init(); let app_state = Arc::new(AppState::new()); let (thread_panic_tx, thread_panic_rx) = unbounded::<&'static str>(); @@ -73,9 +76,8 @@ fn main2() { #[cfg(feature = "dhat-heap")] let dhat_analysis_start = std::time::Instant::now(); #[cfg(feature = "dhat-heap")] - log::info!( - "[{}::main] Starting dhat heap profiler for {} seconds", - module_path!(), + tracing::info!( + "Starting dhat heap profiler for {} seconds", dhat_analysis_time.as_secs() ); @@ -95,11 +97,7 @@ fn main2() { match thread_panic_rx.try_recv() { Ok(panic_details) => { - log::error!( - "[{}::main] Thread panicked: {:?}", - module_path!(), - panic_details - ); + tracing::error!("Thread panicked: {:?}", panic_details); exit(1); } Err(_) => {} @@ -107,3 +105,15 @@ fn main2() { } }) } + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn test_main() { + // setup logging + init_tracing(); + tracing::info!("Running main test"); + } +} diff --git a/server/src/mock/init.rs b/server/src/mock/init.rs index 3d8e6715..f9f5e728 100644 --- a/server/src/mock/init.rs +++ b/server/src/mock/init.rs @@ -13,11 +13,9 @@ use { #[cfg(feature = "mock-machine")] pub fn init_mock(app_state: Arc) -> Result<(), anyhow::Error> { - log::info!("[{}::init_mock] Initializing mock machines", module_path!()); - // For mock devices, we need to manually create and add them to the machine manager // since they won't be detected by the serial detection loop - smol::block_on(async { + return smol::block_on(async { // Create a mock serial device manually let (device_thread_panic_tx, _device_thread_panic_rx) = smol::channel::unbounded(); let serial_params = SerialDeviceNewParams { @@ -48,25 +46,15 @@ pub fn init_mock(app_state: Arc) -> Result<(), anyhow::Error> { .main_namespace; let event = MachinesEventBuilder().build(app_state_event.clone()).await; main_namespace.emit_cached(MainNamespaceEvents::MachinesEvent(event)); - - log::info!( - "[{}::init_mock] Mock machine added successfully", - module_path!() - ); + Ok(()) } Err(e) => { - log::error!( - "[{}::init_mock] Failed to create mock serial device: {}", - module_path!(), - e - ); + tracing::error!("Failed to create mock serial device: {}", e); + return Err(e); } } }); - log::info!( - "[{}::init_mock] Mock machines initialized successfully", - module_path!() - ); + tracing::info!("Mock machines initialized successfully"); Ok(()) } diff --git a/server/src/rest/handlers/machine_mutation.rs b/server/src/rest/handlers/machine_mutation.rs index 4f8e0209..92fbf1d6 100644 --- a/server/src/rest/handlers/machine_mutation.rs +++ b/server/src/rest/handlers/machine_mutation.rs @@ -47,6 +47,15 @@ async fn _post_machine_mutate( } }; + // log + tracing::info!( + machine = %body.machine_identification_unique, + data = ?body.data, + "Mutating machine" + ); + let span = tracing::info_span!("machine_mutate", machine = %body.machine_identification_unique); + let _span = span.enter(); + // lock machine let mut machine_guard = machine.lock().await; diff --git a/server/src/rest/init.rs b/server/src/rest/init.rs index 6fe24874..250efd59 100644 --- a/server/src/rest/init.rs +++ b/server/src/rest/init.rs @@ -9,7 +9,8 @@ use smol::channel::Sender; use std::sync::Arc; use std::thread::JoinHandle; use tower_http::cors::CorsLayer; -use tower_http::trace::TraceLayer; +use tower_http::trace::{DefaultMakeSpan, DefaultOnRequest, DefaultOnResponse, TraceLayer}; +use tracing::Level; pub fn init_api( thread_panic_tx: Sender<&'static str>, @@ -20,20 +21,34 @@ pub fn init_api( .spawn(|| { send_panic("ApiThread", thread_panic_tx); - let rt = tokio::runtime::Runtime::new().expect("Failed to create runtime"); + let rt = tokio::runtime::Builder::new_multi_thread() + .thread_name("tokio") + .enable_io() + .enable_time() + .build() + .expect("Failed to create runtime"); + rt.spawn(async { // allow all CORS requests let cors = CorsLayer::permissive(); - //setup logging - // TODO: this codes makes etehrcrab crash - // tracing_subscriber::fmt() - // .with_max_level(tracing::Level::DEBUG) - // .init(); - // creat socketio layer let socketio_layer = init_socketio(&app_state).await; + // Create a more detailed trace layer for HTTP requests + let trace_layer = TraceLayer::new_for_http() + .make_span_with( + DefaultMakeSpan::new() + .level(Level::DEBUG) + .include_headers(false), + ) + .on_request(DefaultOnRequest::new().level(Level::TRACE)) + .on_response( + DefaultOnResponse::new() + .level(Level::TRACE) + .include_headers(false), + ); + // make axum server to serve the data on /ethercat let app = axum::Router::new() .route( @@ -43,12 +58,14 @@ pub fn init_api( .route("/api/v1/machine/mutate", post(post_machine_mutate)) .layer(socketio_layer) .layer(cors) - .layer(TraceLayer::new_for_http()) + .layer(trace_layer) .with_state(app_state); let listener = tokio::net::TcpListener::bind("0.0.0.0:3001") .await .expect("Failed to bind to port 3001"); + + tracing::info!("Starting HTTP server on 0.0.0.0:3001"); axum::serve(listener, app).await.expect("Failed to serve"); }); diff --git a/server/src/rest/util.rs b/server/src/rest/util.rs index 2990ea38..bd8a238a 100644 --- a/server/src/rest/util.rs +++ b/server/src/rest/util.rs @@ -11,7 +11,7 @@ impl ResponseUtil { let json = match serde_json::to_string(&json!({ "error": message })) { Ok(json) => json, Err(e) => { - log::error!("Failed to serialize error message: {}", e); + tracing::error!("Failed to serialize error message: {}", e); return Response::builder() .status(StatusCode::INTERNAL_SERVER_ERROR) .body(Body::empty()) @@ -29,7 +29,7 @@ impl ResponseUtil { let json = match serde_json::to_string(&data) { Ok(json) => json, Err(e) => { - log::error!("Failed to serialize response data: {}", e); + tracing::error!("Failed to serialize response data: {}", e); return ResponseUtil::error("Failed to serialize response data"); } }; @@ -45,7 +45,7 @@ impl ResponseUtil { let json = match serde_json::to_string(&json!({ "error": message })) { Ok(json) => json, Err(e) => { - log::error!("Failed to serialize not found message: {}", e); + tracing::error!("Failed to serialize not found message: {}", e); return ResponseUtil::error("Failed to serialize not found message"); } }; diff --git a/server/src/serial/init.rs b/server/src/serial/init.rs index 748a9cb1..49531251 100644 --- a/server/src/serial/init.rs +++ b/server/src/serial/init.rs @@ -43,7 +43,6 @@ pub fn init_serial( if !result.added.is_empty() || !result.removed.is_empty() { // sync serial device discovery to machine manager { - println!("{:?}", result); let mut machine_guard = app_state_clone.machines.write().await; // turn added devices into machines for (device_identifiaction, device) in result.added { diff --git a/server/src/socketio/init.rs b/server/src/socketio/init.rs index 49b45ea8..a8586001 100644 --- a/server/src/socketio/init.rs +++ b/server/src/socketio/init.rs @@ -5,12 +5,14 @@ use crate::app_state::AppState; use control_core::socketio::namespace_id::NamespaceId; use socketioxide::extract::SocketRef; use socketioxide::layer::SocketIoLayer; +use tracing::{info_span, span}; +use tracing_futures::Instrument; pub async fn init_socketio(app_state: &Arc) -> SocketIoLayer { // create let (socketio_layer, io) = socketioxide::SocketIoBuilder::new() - .max_buffer_size(1024) - .build_layer(); + .max_buffer_size(1024) + .build_layer(); // Clone app_state for the first handler let app_state_main = app_state.clone(); @@ -23,24 +25,13 @@ pub async fn init_socketio(app_state: &Arc) -> SocketIoLayer { // Clone app_state for the second handler let app_state_machine = app_state.clone(); - match io.dyn_ns( + if let Err(err) = io.dyn_ns( "/machine/{vendor}/{machine}/{serial}", move |socket: SocketRef| { handle_socket_connection(socket, app_state_machine.clone()); }, ) { - Ok(_) => { - // log - log::info!("Machine namespace created"); - } - Err(err) => { - // log - log::error!( - "[{}::init_socketio] Failed to parse machine namespace: {}", - module_path!(), - err - ); - } + tracing::error!("Failed to detect machine namespace: {}", err); } // set the io to the app state @@ -54,11 +45,7 @@ fn handle_socket_connection(socket: SocketRef, app_state: Arc) { let namespace_id = match NamespaceId::from_str(socket.ns()) { Ok(namespace_id) => namespace_id, Err(err) => { - log::error!( - "[{}::handle_socket_connection] Failed to parse namespace id: {}", - module_path!(), - err - ); + tracing::error!("Failed to parse NamespaceId: {}", err); return; } }; @@ -77,10 +64,10 @@ fn setup_disconnection(socket: SocketRef, namespace_id: NamespaceId, app_state: // Spawn async task to avoid blocking and potential deadlocks smol::spawn(async move { - log::debug!( - "Socket disconnected {} from namespace {}", - socket.id, - namespace_id + tracing::debug!( + socket = ?socket.id, + namespace = %namespace_id, + "Socket disconnected from namespace", ); let mut socketio_namespaces_guard = app_state.socketio_setup.namespaces.write().await; @@ -103,42 +90,51 @@ fn setup_connection(socket: SocketRef, namespace_id: NamespaceId, app_state: Arc let namespace_id_clone = namespace_id.clone(); let app_state_clone = app_state.clone(); - smol::spawn(async move { - let mut socketio_namespaces_guard = app_state_clone.socketio_setup.namespaces.write().await; - socketio_namespaces_guard - .apply_mut( - namespace_id_clone.clone(), - &app_state_clone, - |namespace_interface| { - match namespace_interface { - Ok(namespace_interface) => { - // First subscribe the socket - namespace_interface.subscribe(socket_clone.clone()); - log::debug!("Socket {} subscribed to namespace {}", socket_clone.id, namespace_id_clone); - - // Then re-emit cached events - namespace_interface.reemit(socket_clone.clone()); - log::debug!("Reemit completed for socket {} in namespace {}", socket_clone.id, namespace_id_clone); - - log::info!( - "Socket {} was connected to namespace {}", - socket_clone.id, - namespace_id_clone - ); + let span = info_span!( + "socketio_connection", + socket = ?socket_clone.id, + namespace = %namespace_id_clone, + "Connecting socket to namespace" + ); + + smol::spawn( + async move { + let mut socketio_namespaces_guard = + app_state_clone.socketio_setup.namespaces.write().await; + socketio_namespaces_guard + .apply_mut( + namespace_id_clone.clone(), + &app_state_clone, + |namespace_interface| { + match namespace_interface { + Ok(namespace_interface) => { + // First subscribe the socket + namespace_interface.subscribe(socket_clone.clone()); + + // Then re-emit cached events + namespace_interface.reemit(socket_clone.clone()); + } + Err(err) => { + tracing::warn!( + socket = ?socket_clone.id, + namespace = %namespace_id_clone, + "Couln't subscribe socket to namespace, disconnecting: {:?}", + err + ); + let _ = socket_clone.disconnect(); + } } - Err(err) => { - log::warn!( - "Socket connection failed for {} in namespace {}, disconnecting: {:?}", - socket_clone.id, - namespace_id_clone, - err - ); - let _ = socket_clone.disconnect(); - } - } - }, - ) - .await; - }) + }, + ) + .await; + } + .instrument(span), + ) .detach(); + + tracing::info!( + socket = ?socket.id, + namespace = %namespace_id, + "Socket connected to namespace", + ); } diff --git a/server/src/socketio/main_namespace/mod.rs b/server/src/socketio/main_namespace/mod.rs index f7d425fa..19c3358f 100644 --- a/server/src/socketio/main_namespace/mod.rs +++ b/server/src/socketio/main_namespace/mod.rs @@ -30,11 +30,7 @@ where let generic_event = match event.event_value() { Ok(event) => event, Err(err) => { - log::error!( - "[{}::emit_cached] Failed to event.event_value(): {:?}", - module_path!(), - err - ); + tracing::error!("Failed to event.event_value(): {:?}", err); return; } };