improve logging

3 files changed, 69 insertions, 82 deletions

diff --git a/src/client.rs b/src/client.rs
index 391d510..bba842c 100644
--- a/src/client.rs
+++ b/src/client.rs
@@ -87,7 +87,7 @@ impl Client {
                                 Error::NoSession => {}
                                 Error::Disconnected => {}
                                 _ => {
-                                    println!("ip transmission failed: {}", e);
+                                    println!("[pppoe] ip transmit error: {}", e);
                                 }
                             },
                         },
@@ -272,8 +272,8 @@ impl Client {
         thread::spawn(move || {
             while this.state() == state {
                 match this.send(&buf) {
-                    Ok(_) => println!("(re)transmission: {}", &msg),
-                    Err(e) => println!("(re)transmission failed: {}", e),
+                    Ok(_) => println!("[pppoe] (re)transmit {}", &msg),
+                    Err(e) => println!("[pppoe] (re)transmit error: {}", e),
                 }
 
                 thread::sleep(Duration::from_secs(3));
@@ -290,8 +290,8 @@ impl Client {
             let mut i = 1;
             while this.state() == state && i <= max {
                 match this.send(&buf) {
-                    Ok(_) => println!("(re)transmission {}/{}: {}", i, max, &msg),
-                    Err(e) => println!("(re)transmission {}/{} failed: {}", i, max, e),
+                    Ok(_) => println!("[pppoe] (re)transmit {}/{}: {}", i, max, &msg),
+                    Err(e) => println!("[pppoe] (re)transmit {}/{} error: {}", i, max, e),
                 }
 
                 thread::sleep(Duration::from_secs(3));
@@ -354,9 +354,9 @@ impl Client {
         self.set_state(State::Discovery);
 
         self.new_discovery_packet(&mut discovery)?;
-        self.send_while_state(&discovery, State::Discovery, "PADI");
+        self.send_while_state(&discovery, State::Discovery, "padi");
 
-        println!("discovering...");
+        println!("[pppoe] send padi");
         Ok(())
     }
 
@@ -384,7 +384,7 @@ impl Client {
         self.new_lcp_packet(request)?;
         self.send(request)?;
 
-        println!("requested LCP configuration");
+        println!("[pppoe] send lcp configure-req");
         Ok(())
     }
 
@@ -415,7 +415,7 @@ impl Client {
         self.new_ipcp_packet(request)?;
         self.send(request)?;
 
-        println!("requested IPCP configuration");
+        println!("[pppoe] send ipcp configure-req");
         Ok(())
     }
 
@@ -446,7 +446,7 @@ impl Client {
                 let opts: Vec<lcp::ConfigOption> =
                     lcp::ConfigOptionIterator::new(lcp.payload()).collect();
 
-                println!("received LCP configuration request, options: {:?}", opts);
+                println!("[pppoe] recv lcp configure-req, opts: {:?}", opts);
 
                 let limit = lcp.payload().len();
 
@@ -464,10 +464,7 @@ impl Client {
                 self.new_lcp_packet(ack)?;
                 self.send(ack)?;
 
-                println!(
-                    "acknowledged LCP configuration request, options: {:?}",
-                    opts
-                );
+                println!("[pppoe] ack lcp configure-req, opts: {:?}", opts);
                 Ok(())
             }
             lcp::CONFIGURE_ACK => {
@@ -481,20 +478,14 @@ impl Client {
                     return Err(Error::AckedWrongOptions);
                 }
 
-                println!(
-                    "link configuration acknowledged by peer, options: {:?}",
-                    opts
-                );
+                println!("[pppoe] recv configure-ack, opts: {:?}", opts);
                 Ok(())
             }
             lcp::CONFIGURE_NAK => {
                 let opts: Vec<lcp::ConfigOption> =
                     lcp::ConfigOptionIterator::new(lcp.payload()).collect();
 
-                println!(
-                    "the following LCP configuration options were not acknowledged: {:?}",
-                    opts
-                );
+                println!("[pppoe] recv lcp configure-nak, opts: {:?}", opts);
 
                 self.terminate(Err(Error::ConfigNak));
                 Ok(())
@@ -503,10 +494,7 @@ impl Client {
                 let opts: Vec<lcp::ConfigOption> =
                     lcp::ConfigOptionIterator::new(lcp.payload()).collect();
 
-                println!(
-                    "the following LCP configuration options were rejected: {:?}",
-                    opts
-                );
+                println!("[pppoe] recv lcp configure-reject, opts: {:?}", opts);
 
                 self.terminate(Err(Error::ConfigReject));
                 Ok(())
@@ -539,7 +527,7 @@ impl Client {
 
                 self.set_state(State::Terminated);
 
-                println!("acknowledged LCP termination request, reason: {}", reason);
+                println!("[pppoe] ack lcp terminate-req, reason: {}", reason);
                 Ok(())
             }
             lcp::TERMINATE_ACK => {
@@ -550,7 +538,7 @@ impl Client {
                 self.inner.write().unwrap().error = format!("{:?}", Error::UnexpectedTermAck);
                 self.set_state(State::Terminated);
 
-                println!("peer acknowledged unrequested link termination");
+                println!("[pppoe] recv unexpected lcp terminate-ack");
                 Ok(())
             }
             _ => Err(Error::InvalidLcpCode(lcp_code)),
@@ -591,17 +579,17 @@ impl Client {
                 self.new_chap_packet(response)?;
                 self.send(response)?;
 
-                println!("solved CHAP-MD5 challenge");
+                println!("[pppoe] solve CHAP-MD5 challenge");
                 Ok(())
             }
             chap::SUCCESS => {
-                println!("authentication succeeded");
+                println!("[pppoe] auth success");
 
                 self.configure_ip()?;
                 Ok(())
             }
             chap::FAILURE => {
-                println!("authentication failed");
+                println!("[pppoe] auth failure");
                 Ok(())
             }
             _ => Err(Error::InvalidChapCode(chap_code)),
@@ -617,7 +605,7 @@ impl Client {
                 let opts: Vec<ipcp::ConfigOption> =
                     ipcp::ConfigOptionIterator::new(ipcp.payload()).collect();
 
-                println!("received IPCP configuration request, options: {:?}", opts);
+                println!("[pppoe] recv ipcp configure-req, opts: {:?}", opts);
 
                 let mut ip_config = self.ip_config();
 
@@ -651,10 +639,7 @@ impl Client {
                 self.new_ipcp_packet(ack)?;
                 self.send(ack)?;
 
-                println!(
-                    "ackknowledged IPCP configuration request, options: {:?}",
-                    opts
-                );
+                println!("[pppoe] ack ipcp configure-req, opts: {:?}", opts);
 
                 Ok(())
             }
@@ -700,10 +685,9 @@ impl Client {
                 self.set_ip_config(ip_config);
                 tx.send(ip_config)?;
 
-                println!("ip configuration acknowledged by peer, options: {:?}", opts);
-
+                println!("[pppoe] recv ipcp configure-ack, opts: {:?}", opts);
                 println!(
-                    "ip session opened, addr={}, rtr={}, dns1={}, dns2={}",
+                    "[pppoe] open ipcp, addr={}, rtr={}, dns1={}, dns2={}",
                     ip_config.addr, ip_config.rtr, ip_config.dns1, ip_config.dns2
                 );
                 Ok(())
@@ -712,7 +696,7 @@ impl Client {
                 let opts: Vec<ipcp::ConfigOption> =
                     ipcp::ConfigOptionIterator::new(ipcp.payload()).collect();
 
-                println!("obtained configuration via IPCP NAK: {:?}", opts);
+                println!("[pppoe] recv ipcp configure-nak, opts: {:?}", opts);
 
                 let limit = ipcp.payload().len();
 
@@ -727,17 +711,14 @@ impl Client {
                 self.new_ipcp_packet(request)?;
                 self.send(request)?;
 
-                println!("verifying configuration via IPCP request");
+                println!("[pppoe] send ipcp configure-req");
                 Ok(())
             }
             ipcp::CONFIGURE_REJECT => {
                 let opts: Vec<ipcp::ConfigOption> =
                     ipcp::ConfigOptionIterator::new(ipcp.payload()).collect();
 
-                println!(
-                    "the following IPCP configuration options were rejected: {:?}",
-                    opts
-                );
+                println!("[pppoe] recv ipcp configure-reject, opts: {:?}", opts);
 
                 self.terminate(Err(Error::ConfigReject));
                 Ok(())
@@ -802,7 +783,7 @@ impl Client {
 
                     if self.state() == State::Discovery {
                         println!(
-                            "accepting offer from MAC {}, AC {}",
+                            "[pppoe] recv pado from mac {}, ac {}",
                             remote_mac_str, ac_name
                         );
 
@@ -820,11 +801,14 @@ impl Client {
                         self.set_state(State::Requesting);
 
                         self.new_discovery_packet(&mut request)?;
-                        self.send_while_state_max(&request, State::Requesting, 10, "PADR");
+                        self.send_while_state_max(&request, State::Requesting, 10, "padr");
 
-                        println!("requesting...");
+                        println!("[pppoe] send padr");
                     } else {
-                        println!("ignoring offer from MAC {}, AC {}", remote_mac_str, ac_name);
+                        println!(
+                            "[pppoe] ignore pado from mac {}, ac {}",
+                            remote_mac_str, ac_name
+                        );
                     }
 
                     Ok(())
@@ -835,7 +819,7 @@ impl Client {
                             NonZeroU16::new(header.session_id()).ok_or(Error::ZeroSession)?;
 
                         self.set_state(State::Session(session_id));
-                        println!("session established, ID {}", session_id);
+                        println!("[pppoe] recv pads, id {}", session_id);
 
                         thread::sleep(Duration::from_secs(1));
                         self.configure_link()?;
@@ -849,13 +833,16 @@ impl Client {
                     self.set_state(State::Terminated);
                     self.inner.write().unwrap().socket.close();
 
-                    println!("session terminated by peer (PADT), MAC {}", remote_mac_str);
+                    println!("[pppoe] recv padt");
                     return Ok(());
                 }
                 _ => Err(Error::InvalidCode(code)),
             } {
                 Ok(_) => {}
-                Err(e) => println!("error processing packet from MAC {}: {}", remote_mac_str, e),
+                Err(e) => println!(
+                    "[pppoe] recv invalid pkt from mac {}: {}",
+                    remote_mac_str, e
+                ),
             }
 
             if self.state() == State::Terminated {
@@ -863,9 +850,9 @@ impl Client {
 
                 let why = self.why_terminated();
                 if why.is_empty() {
-                    println!("session closed");
+                    println!("[pppoe] session closed");
                 } else {
-                    println!("session closed: {}", why);
+                    println!("[pppoe] session closed: {}", why);
                 }
 
                 return Ok(());
diff --git a/src/error.rs b/src/error.rs
index b45ec93..eb34bbf 100644
--- a/src/error.rs
+++ b/src/error.rs
@@ -7,49 +7,49 @@ use thiserror::Error;
 
 #[derive(Debug, Error)]
 pub enum Error {
-    #[error("client has already been started")]
+    #[error("client already started")]
     AlreadyActive,
     #[error("no active PPPoE session")]
     NoSession,
-    #[error("bytes transmitted is not equal to request size")]
+    #[error("bytes sent not equal to pkt size")]
     PartialTransmission,
-    #[error("number of retransmissions exceeded: {0}")]
+    #[error("too many retransmissions: {0}")]
     TooManyRetransmissions(String),
-    #[error("invalid packet code {0}")]
+    #[error("invalid pkt code {0}")]
     InvalidCode(u8),
-    #[error("unexpected PADS")]
+    #[error("unexpected pads")]
     UnexpectedPads,
-    #[error("session ID is zero")]
+    #[error("session id can't be zero")]
     ZeroSession,
-    #[error("unexpected PPP session traffic")]
+    #[error("unexpected ppp session traffic")]
     UnexpectedPpp,
-    #[error("invalid PPP sub-protocol {0}")]
+    #[error("invalid ppp sub-protocol {0}")]
     InvalidProtocol(u16),
-    #[error("invalid LCP code {0}")]
+    #[error("invalid lcp code {0}")]
     InvalidLcpCode(u8),
-    #[error("configuration acknowledged, but options differ from request")]
+    #[error("configure-ack, but opts don't match req")]
     AckedWrongOptions,
-    #[error("configuration not acknowledged")]
+    #[error("configure-nak")]
     ConfigNak,
-    #[error("configuration rejected")]
+    #[error("configure-reject")]
     ConfigReject,
-    #[error("unexpected acknowledgement of link termination")]
+    #[error("unexpected lcp terminate-ack")]
     UnexpectedTermAck,
-    #[error("invalid CHAP code {0}")]
+    #[error("invalid chap code {0}")]
     InvalidChapCode(u8),
-    #[error("invalid IPCP code {0}")]
+    #[error("invalid ipcp code {0}")]
     InvalidIpcpCode(u8),
-    #[error("peer did not assign us an IP address")]
+    #[error("no ip addr in ipcp configure-nak")]
     MissingIpAddr,
-    #[error("peer did not send us a primary DNS server")]
+    #[error("no dns1 in ipcp configure-nak")]
     MissingPrimaryDns,
-    #[error("peer did not send us a secondary DNS server")]
+    #[error("no dns2 in ipcp configure-nak")]
     MissingSecondaryDns,
-    #[error("no ip connection")]
+    #[error("ipcp closed")]
     Disconnected,
     #[error("io error")]
     Io(#[from] io::Error),
-    #[error("failed to convert string from UTF-8")]
+    #[error("can't create string from UTF-8")]
     Utf8(#[from] string::FromUtf8Error),
     #[error("mpsc send error")]
     MpscSendBytes(#[from] mpsc::SendError<Vec<u8>>),
@@ -57,15 +57,15 @@ pub enum Error {
     MpscSendBytesOpt(#[from] mpsc::SendError<Option<Vec<u8>>>),
     #[error("mpsc send error")]
     MpscSendIpConfig(#[from] mpsc::SendError<IpConfig>),
-    #[error("mpsc receive error")]
+    #[error("mpsc recv error")]
     MpscRecv(#[from] mpsc::RecvError),
     #[error("pppoe error: {0:?}")]
     Pppoe(pppoe::error::Error),
     #[error("pppoe parse error: {0:?}")]
     PppoeParse(pppoe::error::ParseError),
-    #[error("rsdsl netlink(d) error")]
+    #[error("rsdsl_netlinkd error")]
     RsdslNetlinkd(#[from] rsdsl_netlinkd::error::Error),
-    #[error("serde json error")]
+    #[error("serde_json error")]
     SerdeJson(#[from] serde_json::Error),
 }
 
diff --git a/src/main.rs b/src/main.rs
index 1752d81..60fdd03 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -32,7 +32,7 @@ fn tun2ppp(tx: mpsc::Sender<Option<Vec<u8>>>, tun: Arc<Iface>) -> Result<()> {
         let ether_type = NE::read_u16(&buf[2..4]);
         if ether_type != IPV4 {
             println!(
-                "dropping outbound non-IPv4 packet, EtherType: 0x{:04x}",
+                "[pppoe] drop outbound non-ipv4 pkt, ethertype: 0x{:04x}",
                 ether_type
             );
             continue;
@@ -73,10 +73,10 @@ fn main() -> Result<()> {
     let mut file = File::open("/data/pppoe.conf")?;
     let config: Config = serde_json::from_reader(&mut file)?;
 
-    println!("read config, launching on interface {}", config.link);
+    println!("[pppoe] read config, launch on interface {}", config.link);
 
     while !link::is_up(config.link.clone())? {
-        println!("waiting for {} to come up", config.link);
+        println!("[pppoe] wait for {} to come up", config.link);
         thread::sleep(Duration::from_secs(8));
     }
 
@@ -108,13 +108,13 @@ fn main() -> Result<()> {
     });
 
     loop {
-        println!("connecting...");
+        println!("[pppoe] connect");
 
         let clt = Client::new(config.clone())?;
 
         clt.run(recv_tx.clone(), send_rx.clone(), ipchange_tx.clone())?;
 
         send_tx.send(None)?;
-        println!("connection lost");
+        println!("[pppoe] disconnect");
     }
 }