Skip to content

Commit 54c66c4

Browse files
lmbollenlmbollen
committed
Add logging
1 parent 114e4e6 commit 54c66c4

4 files changed

Lines changed: 189 additions & 16 deletions

File tree

‎firmware-binaries/demos/soft-ugn-demo-mu-2/Cargo.toml‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -18,7 +18,7 @@ ufmt = "0.2.0"
1818
[dependencies.smoltcp]
1919
version = "0.12.0"
2020
default-features = false
21-
features = ["medium-ip", "medium-ethernet", "proto-ipv4", "socket-tcp"]
21+
features = ["log", "medium-ip", "medium-ethernet", "proto-ipv4", "socket-tcp"]
2222

2323
[dependencies.log]
2424
version = "0.4.21"

‎firmware-binaries/demos/soft-ugn-demo-mu-2/src/main.rs‎

Lines changed: 69 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -10,7 +10,9 @@ use bittide_hal::hals::soft_ugn_demo_mu::devices::{ReceiveRingbuffer, TransmitRi
1010
use bittide_hal::hals::soft_ugn_demo_mu::DeviceInstances;
1111
use bittide_hal::manual_additions::timer::Instant;
1212
use bittide_sys::link_startup::LinkStartup;
13-
use bittide_sys::net_state::{Manager, SmoltcpLink, Subordinate, UgnEdge, UgnReport};
13+
use bittide_sys::net_state::{
14+
Manager, ManagerState, SmoltcpLink, Subordinate, SubordinateState, UgnEdge, UgnReport,
15+
};
1416
use bittide_sys::smoltcp::soft_ugn_ringbuffer::{AlignedReceiveBuffer, RingbufferDevice};
1517
use bittide_sys::stability_detector::Stability;
1618
use core::fmt::Write;
@@ -24,6 +26,7 @@ const INSTANCES: DeviceInstances = unsafe { DeviceInstances::new() };
2426
const LINK_COUNT: usize = 7;
2527
const TCP_BUF_SIZE: usize = 256;
2628
const MANAGER_DNA: [u8; 12] = [133, 129, 48, 4, 64, 192, 105, 1, 1, 0, 2, 64];
29+
const LOG_TICK_EVERY: u32 = 500;
2730

2831
static mut TCP_RX_BUFS: [[u8; TCP_BUF_SIZE]; LINK_COUNT] = [[0; TCP_BUF_SIZE]; LINK_COUNT];
2932
static mut TCP_TX_BUFS: [[u8; TCP_BUF_SIZE]; LINK_COUNT] = [[0; TCP_BUF_SIZE]; LINK_COUNT];
@@ -204,12 +207,30 @@ fn main() -> ! {
204207
info!("Starting manager state machines...");
205208
let mut managers: [Manager; LINK_COUNT] = core::array::from_fn(|_| Manager::new());
206209
let mut done = [false; LINK_COUNT];
210+
let mut last_states: [ManagerState; LINK_COUNT] =
211+
core::array::from_fn(|_| ManagerState::WaitForPhy);
212+
let mut tick: u32 = 0;
207213

214+
trace!("Starting main event loop...");
208215
loop {
216+
tick = tick.wrapping_add(1);
217+
if tick % LOG_TICK_EVERY == 0 {
218+
info!("manager loop tick {}", tick);
219+
}
209220
let now = to_smoltcp_instant(INSTANCES.timer.now());
210221
for link in 0..LINK_COUNT {
211222
let mut sockets = socket_set(&mut sockets_storage[link][..]);
212-
let _ = ifaces[link].poll(now, &mut devices[link], &mut sockets);
223+
let poll_result = ifaces[link].poll(now, &mut devices[link], &mut sockets);
224+
trace!("manager link {} poll result {:?}", link, poll_result);
225+
let socket = sockets.get::<tcp::Socket>(socket_handles[link]);
226+
trace!(
227+
"manager link {} socket open {} active {} can_send {} can_recv {}",
228+
link,
229+
socket.is_open(),
230+
socket.is_active(),
231+
socket.can_send(),
232+
socket.can_recv()
233+
);
213234
let mut smoltcp_link = SmoltcpLink::new(
214235
&mut ifaces[link],
215236
&mut sockets,
@@ -218,13 +239,28 @@ fn main() -> ! {
218239
true,
219240
false,
220241
);
242+
trace!(
243+
"manager link {} step from state {:?}",
244+
link,
245+
managers[link].state()
246+
);
221247
managers[link].step(&mut smoltcp_link);
248+
let state = managers[link].state();
249+
if state != last_states[link] {
250+
info!(
251+
"manager link {} state {:?} -> {:?}",
252+
link, last_states[link], state
253+
);
254+
last_states[link] = state;
255+
}
222256
if managers[link].is_done() {
257+
trace!("manager link {} is done", link);
223258
done[link] = true;
224259
}
225260
}
226261

227262
if done.iter().all(|v| *v) {
263+
info!("All manager links done");
228264
break;
229265
}
230266
}
@@ -259,15 +295,32 @@ fn main() -> ! {
259295
info!("Starting subordinate state machines...");
260296
let mut subordinates: [Subordinate; LINK_COUNT] =
261297
core::array::from_fn(|_| Subordinate::new());
298+
let mut last_states: [SubordinateState; LINK_COUNT] =
299+
core::array::from_fn(|_| SubordinateState::WaitForPhy);
300+
let mut tick: u32 = 0;
262301
for link in 0..LINK_COUNT {
263302
subordinates[link].set_report(build_report_for_link(link, &capture_ugns[link], &dna));
264303
}
265304

266305
loop {
306+
tick = tick.wrapping_add(1);
307+
if tick % LOG_TICK_EVERY == 0 {
308+
info!("subordinate loop tick {}", tick);
309+
}
267310
let now = to_smoltcp_instant(INSTANCES.timer.now());
268311
for link in 0..LINK_COUNT {
269312
let mut sockets = socket_set(&mut sockets_storage[link][..]);
270-
let _ = ifaces[link].poll(now, &mut devices[link], &mut sockets);
313+
let poll_result = ifaces[link].poll(now, &mut devices[link], &mut sockets);
314+
trace!("subordinate link {} poll result {:?}", link, poll_result);
315+
let socket = sockets.get::<tcp::Socket>(socket_handles[link]);
316+
trace!(
317+
"subordinate link {} socket open {} active {} can_send {} can_recv {}",
318+
link,
319+
socket.is_open(),
320+
socket.is_active(),
321+
socket.can_send(),
322+
socket.can_recv()
323+
);
271324
let mut smoltcp_link = SmoltcpLink::new(
272325
&mut ifaces[link],
273326
&mut sockets,
@@ -276,7 +329,20 @@ fn main() -> ! {
276329
true,
277330
false,
278331
);
332+
trace!(
333+
"subordinate link {} step from state {:?}",
334+
link,
335+
subordinates[link].state()
336+
);
279337
subordinates[link].step(&mut smoltcp_link);
338+
let state = subordinates[link].state();
339+
if state != last_states[link] {
340+
info!(
341+
"subordinate link {} state {:?} -> {:?}",
342+
link, last_states[link], state
343+
);
344+
last_states[link] = state;
345+
}
280346
}
281347
}
282348
}

‎firmware-support/bittide-sys/src/net_state.rs‎

Lines changed: 98 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -158,47 +158,115 @@ impl<'a, 'b> SmoltcpLink<'a, 'b> {
158158
let _ = addrs.push(ip);
159159
}
160160
});
161+
trace!(
162+
"link {} role {:?} ip addrs {:?}",
163+
self.link,
164+
role,
165+
self.iface.ip_addrs()
166+
);
161167
}
162168

163169
pub fn connect(&mut self, peer_ip: [u8; 4]) -> bool {
164170
let socket = self.sockets.get_mut::<tcp::Socket>(self.socket_handle);
165171
if !socket.is_open() && !socket.is_active() {
166172
let cx = self.iface.context();
167-
let _ = socket.connect(
173+
match socket.connect(
168174
cx,
169175
(
170176
IpAddress::v4(peer_ip[0], peer_ip[1], peer_ip[2], peer_ip[3]),
171177
TCP_SERVER_PORT,
172178
),
173179
TCP_CLIENT_PORT,
174-
);
180+
) {
181+
Ok(()) => {
182+
debug!(
183+
"link {} connect requested to {:?}:{} from {}",
184+
self.link, peer_ip, TCP_SERVER_PORT, TCP_CLIENT_PORT
185+
);
186+
}
187+
Err(err) => {
188+
debug!("link {} connect error: {:?}", self.link, err);
189+
}
190+
}
175191
}
192+
trace!(
193+
"link {} connect state open {} active {} can_send {} can_recv {} may_recv {}",
194+
self.link,
195+
socket.is_open(),
196+
socket.is_active(),
197+
socket.can_send(),
198+
socket.can_recv(),
199+
socket.may_recv()
200+
);
176201
socket.is_active()
177202
}
178203

179204
pub fn listen(&mut self) -> bool {
180205
let socket = self.sockets.get_mut::<tcp::Socket>(self.socket_handle);
181206
if !socket.is_open() {
182-
let _ = socket.listen(TCP_SERVER_PORT);
207+
match socket.listen(TCP_SERVER_PORT) {
208+
Ok(()) => {
209+
debug!("link {} listen on port {}", self.link, TCP_SERVER_PORT);
210+
}
211+
Err(err) => {
212+
debug!("link {} listen error: {:?}", self.link, err);
213+
}
214+
}
183215
}
216+
trace!(
217+
"link {} listen state open {} active {} can_send {} can_recv {} may_recv {}",
218+
self.link,
219+
socket.is_open(),
220+
socket.is_active(),
221+
socket.can_send(),
222+
socket.can_recv(),
223+
socket.may_recv()
224+
);
184225
socket.is_open()
185226
}
186227

187228
pub fn send(&mut self, data: &[u8]) -> bool {
188229
let socket = self.sockets.get_mut::<tcp::Socket>(self.socket_handle);
189230
if socket.can_send() {
190-
let _ = socket.send_slice(data);
191-
return true;
231+
match socket.send_slice(data) {
232+
Ok(len) => {
233+
trace!("link {} sent {} bytes", self.link, len);
234+
return true;
235+
}
236+
Err(err) => {
237+
debug!("link {} send error: {:?}", self.link, err);
238+
}
239+
}
240+
} else {
241+
trace!(
242+
"link {} send blocked open {} active {}",
243+
self.link,
244+
socket.is_open(),
245+
socket.is_active()
246+
);
192247
}
193248
false
194249
}
195250

196251
pub fn recv(&mut self, buf: &mut [u8]) -> Option<usize> {
197252
let socket = self.sockets.get_mut::<tcp::Socket>(self.socket_handle);
198253
if socket.can_recv() {
199-
if let Ok(len) = socket.recv_slice(buf) {
200-
return Some(len);
254+
match socket.recv_slice(buf) {
255+
Ok(len) => {
256+
trace!("link {} recv {} bytes", self.link, len);
257+
return Some(len);
258+
}
259+
Err(err) => {
260+
debug!("link {} recv error: {:?}", self.link, err);
261+
}
201262
}
263+
} else {
264+
trace!(
265+
"link {} recv blocked open {} active {}",
266+
self.link,
267+
socket.is_open(),
268+
socket.is_active()
269+
);
202270
}
203271
None
204272
}
@@ -243,6 +311,7 @@ impl Manager {
243311
let prev_state = self.state;
244312
let next_state = match self.state {
245313
ManagerState::WaitForPhy => {
314+
trace!("Checking phy ready on link {}", link.link());
246315
if link.phy_ready() {
247316
debug!("manager phy ready on link {}", link.link());
248317
ManagerState::SetupInterface
@@ -257,6 +326,11 @@ impl Manager {
257326
}
258327
ManagerState::WaitForSession => {
259328
let peer_ip = ip_for_link(NodeRole::Subordinate, link.link());
329+
trace!(
330+
"manager attempting connect to peer {:?} on link {}",
331+
peer_ip,
332+
link.link()
333+
);
260334
if link.connect(peer_ip) {
261335
debug!("manager connected link {} peer {:?}", link.link(), peer_ip);
262336
self.identifying_sent = false;
@@ -269,6 +343,7 @@ impl Manager {
269343
}
270344
}
271345
ManagerState::Identifying => {
346+
trace!("manager identifying link {}", link.link());
272347
if !self.identifying_sent {
273348
self.nonce = self.next_nonce();
274349
let msg = encode_who_are_you(self.nonce);
@@ -300,6 +375,7 @@ impl Manager {
300375
}
301376
}
302377
ManagerState::ReceivingUgns => {
378+
trace!("manager receiving ugns on link {}", link.link());
303379
if !self.ugn_dump_sent {
304380
let msg = [MSG_UGN_DUMP];
305381
if link.send(&msg) {
@@ -456,6 +532,11 @@ impl Subordinate {
456532
let prev_state = self.state;
457533
let next_state = match self.state {
458534
SubordinateState::WaitForPhy => {
535+
trace!(
536+
"subordinate state {:?} checking phy ready on link {}",
537+
self.state,
538+
link.link()
539+
);
459540
if link.phy_ready() {
460541
debug!("subordinate phy ready on link {}", link.link());
461542
SubordinateState::SetupInterface
@@ -469,6 +550,11 @@ impl Subordinate {
469550
SubordinateState::WaitForSession
470551
}
471552
SubordinateState::WaitForSession => {
553+
trace!(
554+
"subordinate state {:?} attempting listen on link {}",
555+
self.state,
556+
link.link()
557+
);
472558
if link.listen() {
473559
debug!("subordinate listening on link {}", link.link());
474560
self.reset_handshake();
@@ -480,6 +566,11 @@ impl Subordinate {
480566
}
481567
}
482568
SubordinateState::SendingUgns => {
569+
trace!(
570+
"subordinate state {:?} checking for manager connection on link {}",
571+
self.state,
572+
link.link()
573+
);
483574
if link.timed_out() && !self.ugn_dump_received {
484575
self.reset_handshake();
485576
self.bump_retry_or_fail(SubordinateState::SendingUgns)

0 commit comments

Comments
 (0)