telnet: Improve debugging, separate IAC vs. data tracing

ESP8266-based WiFi serial modem emulator ROM

This properly implements WONT/DONT support which we were lacking,
and fixes negotiation with NetBSD telnetd (such as sdf.org) by
responding to ENCRYPT with DONT rather than WONT.

jcs.org 4 years ago 29c0aa00 7103fbd8

+253 -98

2 changed files

expand all

telnet.cpp

wifippp.h

+250 -97

telnet.cpp

··· 20 20 WiFiClient telnet; 21 21 22 22 enum { 23 - TELNET_STATE_DISCONNECTED = 1, 23 + TELNET_STATE_DISCONNECTED = 0, 24 24 TELNET_STATE_CONNECTED, 25 25 TELNET_STATE_IAC, 26 - TELNET_STATE_IAC_SB, 27 26 TELNET_STATE_IAC_WILL, 27 + TELNET_STATE_IAC_WONT, 28 28 TELNET_STATE_IAC_DO, 29 + TELNET_STATE_IAC_DONT, 30 + TELNET_STATE_IAC_SB, 29 31 }; 30 32 31 33 uint8_t telnet_state = TELNET_STATE_DISCONNECTED; 32 34 uint8_t telnet_sb[64]; 33 35 uint8_t telnet_sb_len = 0; 34 - bool telnet_echoing = true; 35 36 36 37 #define SE 240 /* end of sub-negotiation options */ 37 38 #define SB 250 /* start of sub-negotiation options */ ··· 44 45 #define IS 0 /* sub-negotiation */ 45 46 #define SEND 1 /* sub-negotiation */ 46 47 48 + #define IAC_BINARY 0 /* Transmit Binary */ 47 49 #define IAC_ECHO 1 /* Echo Option */ 48 50 #define IAC_SGA 3 /* Suppress Go Ahead Option */ 49 51 #define IAC_STATUS 5 /* Status Option */ ··· 72 74 #define IAC_LINEMODE 34 /* Linemode Option */ 73 75 #define IAC_XDISPLOC 35 /* X Display Location Option */ 74 76 #define IAC_ENVIRON 36 /* Environment Option */ 77 + #define IAC_AUTH 37 /* Authentication */ 78 + #define IAC_ENCRYPT 38 /* Encryption Option */ 75 79 #define IAC_NEWENV 39 /* Environment Option */ 76 80 #define IAC_CHARSET 42 /* Charset Option */ 77 81 #define IAC_COMPORT 44 /* Com Port Control Option */ 78 82 79 - #if DEBUG 80 - #define TELNET_DEBUG(...) { outputf(__VA_ARGS__) } 83 + #ifdef TELNET_IAC_TRACE 84 + #define TELNET_IAC_DEBUG(...) { syslog.logf(LOG_INFO, __VA_ARGS__); delay(1); } 81 85 #else 82 - #define TELNET_DEBUG(...) {} 86 + #define TELNET_IAC_DEBUG(...) {} 83 87 #endif 84 88 85 - void telnet_process_sb(void); 89 + #ifdef TELNET_DATA_TRACE 90 + #define TELNET_DATA_DEBUG(...) { syslog.logf(LOG_INFO, __VA_ARGS__); delay(1); } 91 + #else 92 + #define TELNET_DATA_DEBUG(...) {} 93 + #endif 86 94 87 95 int 88 96 telnet_connect(char *host, uint16_t port) 89 97 { 90 - if (telnet_state != TELNET_STATE_DISCONNECTED) { 91 - outputf("can't telnet_connect, telnet_state %d\r\n", 92 - telnet_state); 93 - return 1; 94 - } 98 + if (telnet_state != TELNET_STATE_DISCONNECTED) 99 + telnet_disconnect(); 95 100 96 101 if (!telnet.connect(host, port)) 97 102 return 1; ··· 99 104 telnet.setNoDelay(true); 100 105 101 106 telnet_state = TELNET_STATE_CONNECTED; 102 - telnet_echoing = true; 103 107 serial_dcd(true); 108 + 109 + if (settings->telnet) { 110 + /* start by sending things we support */ 111 + TELNET_IAC_DEBUG("%s: -> IAC DO SUPPRESS GO AHEAD", __func__); 112 + telnet.printf("%c%c%c", IAC, DO, IAC_SGA); 113 + TELNET_IAC_DEBUG("%s: -> IAC WILL TTYPE", __func__); 114 + telnet.printf("%c%c%c", IAC, WILL, IAC_TTYPE); 115 + TELNET_IAC_DEBUG("%s: -> IAC WILL NAWS", __func__); 116 + telnet.printf("%c%c%c", IAC, WILL, IAC_NAWS); 117 + TELNET_IAC_DEBUG("%s: -> IAC WILL TSPEED", __func__); 118 + telnet.printf("%c%c%c", IAC, WILL, IAC_TSPEED); 119 + TELNET_IAC_DEBUG("%s: -> IAC WONT LINEMODE", __func__); 120 + telnet.printf("%c%c%c", IAC, WONT, IAC_LINEMODE); 121 + TELNET_IAC_DEBUG("%s: -> IAC DO STATUS", __func__); 122 + telnet.printf("%c%c%c", IAC, DO, IAC_STATUS); 123 + } 124 + 104 125 return 0; 105 126 } 106 127 ··· 127 148 serial_dcd(false); 128 149 } 129 150 130 - void 131 - telnet_process_sb(void) 151 + #ifdef TELNET_IAC_TRACE 152 + static char iac_name[16]; 153 + char * 154 + telnet_iac_name(char iac) 132 155 { 133 - switch (telnet_sb[0]) { 134 - case IAC_TTYPE: 135 - if (telnet_sb[1] != SEND) { 136 - TELNET_DEBUG("%s: server is telling us TYPE? ", 137 - __func__); 138 - goto dump_sb; 139 - } 140 - 141 - TELNET_DEBUG("%s: -> IAC SB TTYPE %s\r\n", __func__, 142 - settings->telnet_tterm); 143 - telnet.printf("%c%c%c%c", IAC, SB, IAC_TTYPE, IS); 144 - for (size_t i = 0; i < sizeof(settings->telnet_tterm); i++) { 145 - if (settings->telnet_tterm[i] == '\0') 146 - break; 156 + if (telnet_state == TELNET_STATE_CONNECTED && iac != IAC) { 157 + sprintf(iac_name, "%d (%c)", iac, iac); 158 + return iac_name; 159 + } 147 160 148 - if (settings->telnet_tterm[i] == IAC) 149 - telnet.write(IAC); 150 - telnet.write(settings->telnet_tterm[i]); 151 - } 152 - telnet.printf("%c%c", IAC, SE); 161 + switch (iac) { 162 + case IAC_ECHO: 163 + sprintf(iac_name, "ECHO"); 164 + break; 165 + case IAC_SGA: 166 + sprintf(iac_name, "SGA"); 167 + break; 168 + case IAC_STATUS: 169 + sprintf(iac_name, "STATUS"); 170 + break; 171 + case IAC_TTYPE: 172 + sprintf(iac_name, "TTYPE"); 153 173 break; 154 174 case IAC_NAWS: 155 - if (telnet_sb[1] != SEND) { 156 - TELNET_DEBUG("%s: server is telling us NAWS? ", 157 - __func__); 158 - goto dump_sb; 159 - } 175 + sprintf(iac_name, "NAWS"); 176 + break; 177 + case IAC_TSPEED: 178 + sprintf(iac_name, "TSPEED"); 179 + break; 180 + case IAC_FLOWCTRL: 181 + sprintf(iac_name, "FLOWCTRL"); 182 + break; 183 + case IAC_LINEMODE: 184 + sprintf(iac_name, "LINEMODE"); 185 + break; 186 + case IAC_ENCRYPT: 187 + sprintf(iac_name, "ENCRYPT"); 188 + break; 189 + case IAC_AUTH: 190 + sprintf(iac_name, "AUTH"); 191 + break; 192 + case IAC_XDISPLOC: 193 + sprintf(iac_name, "XDISPLOC"); 194 + break; 195 + case IAC_NEWENV: 196 + sprintf(iac_name, "NEWENV"); 197 + break; 198 + case IAC_ENVIRON: 199 + sprintf(iac_name, "OLD ENVIRON"); 200 + break; 201 + case SE: 202 + sprintf(iac_name, "SE"); 203 + break; 204 + case SB: 205 + sprintf(iac_name, "SB"); 206 + break; 207 + case WILL: 208 + sprintf(iac_name, "WILL"); 209 + break; 210 + case WONT: 211 + sprintf(iac_name, "WONT"); 212 + break; 213 + case DO: 214 + sprintf(iac_name, "DO"); 215 + break; 216 + case DONT: 217 + sprintf(iac_name, "DONT"); 218 + break; 219 + case IAC: 220 + sprintf(iac_name, "IAC"); 221 + break; 222 + default: 223 + sprintf(iac_name, "%d", iac); 224 + break; 225 + } 226 + return iac_name; 227 + } 228 + #endif 229 + 230 + void 231 + telnet_send_ttype(void) 232 + { 233 + TELNET_IAC_DEBUG("%s: -> IAC SB TTYPE IS %s IAC SE", __func__, 234 + settings->telnet_tterm); 235 + telnet.printf("%c%c%c%c", IAC, SB, IAC_TTYPE, IS); 236 + for (size_t i = 0; i < sizeof(settings->telnet_tterm); i++) { 237 + if (settings->telnet_tterm[i] == '\0') 238 + break; 239 + 240 + if (settings->telnet_tterm[i] == IAC) 241 + telnet.write(IAC); 242 + telnet.write(settings->telnet_tterm[i]); 243 + } 244 + telnet.printf("%c%c", IAC, SE); 245 + } 246 + 247 + void 248 + telnet_send_naws(void) 249 + { 250 + 251 + TELNET_IAC_DEBUG("%s: -> IAC SB NAWS IS %dx%d IAC SE", __func__, 252 + settings->telnet_tts_w, settings->telnet_tts_h); 160 253 161 - TELNET_DEBUG("%s: -> IAC SB NAWS %dx%d\r\n", __func__, 162 - settings->telnet_tts_w, settings->telnet_tts_h); 254 + telnet.printf("%c%c%c", IAC, SB, IAC_NAWS); 255 + 256 + /* we only support 8-bit settings, but NAWS is 16-bit * */ 257 + telnet.write(0); 258 + if (settings->telnet_tts_w == IAC) 259 + telnet.write(IAC); 260 + telnet.write(settings->telnet_tts_w); 163 261 164 - telnet.printf("%c%c%c", IAC, SB, IAC_NAWS); 262 + telnet.write(0); 263 + if (settings->telnet_tts_h == IAC) 264 + telnet.write(IAC); 265 + telnet.write(settings->telnet_tts_h); 165 266 166 - /* we only support 8-bit settings, but NAWS is 16-bit * */ 167 - telnet.write(0); 168 - if (settings->telnet_tts_w == IAC) 169 - telnet.write(IAC); 170 - telnet.write(settings->telnet_tts_w); 267 + telnet.printf("%c%c", IAC, SE); 268 + } 171 269 172 - telnet.write(0); 173 - if (settings->telnet_tts_h == IAC) 174 - telnet.write(IAC); 175 - telnet.write(settings->telnet_tts_h); 270 + void 271 + telnet_send_tspeed(void) 272 + { 273 + TELNET_IAC_DEBUG("%s: -> IAC SB TSPEED IS %d,%d IAC SE", __func__, 274 + Serial.baudRate(), Serial.baudRate()); 176 275 177 - telnet.printf("%c%c", IAC, SE); 178 - break; 179 - default: 180 - TELNET_DEBUG("handle IAC SB:"); 181 - goto dump_sb; 182 - } 276 + telnet.printf("%c%c%c%d,%d", IAC, SB, IAC_TSPEED, Serial.baudRate(), 277 + Serial.baudRate()); 183 278 184 - return; 185 - dump_sb: 186 - for (int i = 0; i < telnet_sb_len; i++) 187 - TELNET_DEBUG(" %02d", telnet_sb[i]); 188 - TELNET_DEBUG("\r\n"); 279 + telnet.printf("%c%c", IAC, SE); 189 280 } 190 281 191 282 int ··· 196 287 if (!telnet.available()) 197 288 return -1; 198 289 199 - b = telnet.read(); 200 - 201 - if (telnet_state != TELNET_STATE_CONNECTED) 202 - TELNET_DEBUG("telnet_state[%d]: 0x%x (%d)\r\n", telnet_state, 203 - b, b); 204 - 205 290 /* when AT$NET=0, just pass everything as-is */ 206 291 if (!settings->telnet) 207 - return b; 292 + return telnet.read(); 293 + 294 + b = telnet.peek(); 295 + if (telnet_state != TELNET_STATE_CONNECTED || b == IAC) 296 + TELNET_IAC_DEBUG("telnet_read[%s]: %s", 297 + (telnet_state == TELNET_STATE_CONNECTED ? "connected" : 298 + (telnet_state == TELNET_STATE_IAC ? "IAC" : 299 + (telnet_state == TELNET_STATE_IAC_WILL ? "WILL" : 300 + (telnet_state == TELNET_STATE_IAC_WONT ? "WONT" : 301 + (telnet_state == TELNET_STATE_IAC_DO ? "DO" : 302 + (telnet_state == TELNET_STATE_IAC_DONT ? "DONT" : 303 + (telnet_state == TELNET_STATE_IAC_SB ? "SB" : "?"))))))), 304 + telnet_iac_name(b)); 208 305 209 306 switch (telnet_state) { 210 307 case TELNET_STATE_CONNECTED: 308 + b = telnet.read(); 211 309 switch (b) { 212 310 case IAC: 213 311 telnet_state = TELNET_STATE_IAC; ··· 217 315 } 218 316 break; 219 317 case TELNET_STATE_IAC: 318 + /* don't consume byte yet */ 220 319 switch (b) { 221 320 case IAC: 222 - /* escaped IAC */ 223 - return b; 321 + /* escaped IAC, return one IAC */ 322 + telnet_state = TELNET_STATE_CONNECTED; 323 + return telnet.read(); 224 324 case WILL: 225 325 /* server can do something */ 226 326 telnet_state = TELNET_STATE_IAC_WILL; 327 + break; 328 + case WONT: 329 + /* server will not do something */ 330 + telnet_state = TELNET_STATE_IAC_WONT; 227 331 break; 228 332 case DO: 229 333 /* server wants us to do something */ 230 334 telnet_state = TELNET_STATE_IAC_DO; 231 335 break; 336 + case DONT: 337 + /* server wants us to not do something */ 338 + telnet_state = TELNET_STATE_IAC_DONT; 339 + break; 232 340 case SB: 233 341 /* sub-negotiate */ 234 342 telnet_state = TELNET_STATE_IAC_SB; 235 343 telnet_sb_len = 0; 236 344 break; 237 345 default: 346 + /* something else, return the original IAC */ 238 347 telnet_state = TELNET_STATE_CONNECTED; 348 + return IAC; 349 + /* this next non-IAC byte will get returned next */ 239 350 } 351 + /* consume byte */ 352 + telnet.read(); 240 353 break; 241 354 case TELNET_STATE_IAC_SB: 242 355 /* keep reading until we see [^IAC] IAC SE */ 356 + b = telnet.read(); 357 + TELNET_IAC_DEBUG("telnet_read: SB[%d] %s", 358 + telnet_sb_len, telnet_iac_name(b)); 243 359 if (b == SE && telnet_sb_len > 0 && 244 360 telnet_sb[telnet_sb_len - 1] == IAC) { 245 - telnet_process_sb(); 361 + TELNET_IAC_DEBUG("telnet_read: processing SB"); 362 + if (telnet_sb[1] == SEND) { 363 + switch (telnet_sb[0]) { 364 + case IAC_TTYPE: 365 + telnet_send_ttype(); 366 + break; 367 + case IAC_NAWS: 368 + telnet_send_naws(); 369 + break; 370 + case IAC_TSPEED: 371 + telnet_send_tspeed(); 372 + break; 373 + default: 374 + TELNET_IAC_DEBUG("unsupported IAC SB %s", 375 + telnet_iac_name(telnet_sb[0])); 376 + } 377 + } else { 378 + syslog.logf(LOG_WARNING, "%s: server is " 379 + "telling us SB %d?", __func__, telnet_sb[0]); 380 + } 246 381 telnet_state = TELNET_STATE_CONNECTED; 247 382 } else { 248 383 if (telnet_sb_len < sizeof(telnet_sb)) 249 384 telnet_sb[telnet_sb_len++] = b; 250 385 else { 251 - outputf("IAC SB overflow!\r\n"); 386 + syslog.logf(LOG_ERR, "IAC SB overflow!"); 252 387 telnet_state = TELNET_STATE_CONNECTED; 388 + telnet_sb_len = 0; 253 389 } 254 390 } 255 391 break; 256 392 case TELNET_STATE_IAC_WILL: 257 - TELNET_DEBUG("telnet_read: IAC WILL %d\r\n", b); 258 - switch (b) { 393 + switch (b = telnet.read()) { 259 394 case IAC_ECHO: 260 - TELNET_DEBUG("telnet_read: -> IAC DO ECHO\r\n"); 395 + TELNET_IAC_DEBUG("telnet_read: -> IAC DO ECHO"); 261 396 telnet.printf("%c%c%c", IAC, DO, b); 262 397 break; 263 - case IAC_TTYPE: 264 - TELNET_DEBUG("telnet_read: -> IAC DO TTYPE\r\n"); 398 + case IAC_SGA: 399 + TELNET_IAC_DEBUG("telnet_read: -> IAC DO SGA"); 265 400 telnet.printf("%c%c%c", IAC, DO, b); 266 401 break; 267 - case IAC_NAWS: 268 - TELNET_DEBUG("telnet_read: -> IAC DO NAWS\r\n"); 269 - telnet.printf("%c%c%c", IAC, DO, b); 270 - break; 271 - case IAC_TSPEED: 272 - TELNET_DEBUG("telnet_read: -> IAC DO TSPEED\r\n"); 273 - telnet.printf("%c%c%c", IAC, DO, b); 402 + case IAC_ENCRYPT: 403 + /* refuse with DONT to satisfy NetBSD's telnetd */ 404 + TELNET_IAC_DEBUG("telnet_read: -> IAC DONT ENCRYPT"); 405 + telnet.printf("%c%c%c", IAC, DONT, b); 274 406 break; 407 + } 408 + telnet_state = TELNET_STATE_CONNECTED; 409 + break; 410 + case TELNET_STATE_IAC_WONT: 411 + switch (b = telnet.read()) { 275 412 default: 276 - TELNET_DEBUG("telnet_read: -> IAC WONT %d\r\n", b); 277 - telnet.printf("%c%c%c", IAC, WONT, b); 413 + /* we don't care about any of these yet */ 278 414 break; 279 415 } 280 416 telnet_state = TELNET_STATE_CONNECTED; 281 417 break; 282 418 case TELNET_STATE_IAC_DO: 419 + b = telnet.read(); 283 420 switch (b) { 284 - case IAC_TTYPE: 285 - TELNET_DEBUG("telnet_read: -> IAC WILL TTYPE\r\n"); 421 + case IAC_BINARY: 422 + TELNET_IAC_DEBUG("telnet_read: -> IAC WILL BINARY"); 286 423 telnet.printf("%c%c%c", IAC, WILL, b); 287 424 break; 288 425 case IAC_NAWS: 289 - TELNET_DEBUG("telnet_read: -> IAC WILL NAWS\r\n"); 290 - telnet.printf("%c%c%c", IAC, WILL, b); 426 + case IAC_TSPEED: 427 + case IAC_TTYPE: 428 + case IAC_FLOWCTRL: 291 429 break; 292 430 case IAC_LINEMODE: 293 431 /* refuse this, we want the server to handle input */ 294 - TELNET_DEBUG("telnet_read: -> IAC WONT LINEMODE\r\n"); 432 + /* FALLTHROUGH */ 433 + default: 434 + TELNET_IAC_DEBUG("telnet_read: -> IAC WONT %s", 435 + telnet_iac_name(b)); 295 436 telnet.printf("%c%c%c", IAC, WONT, b); 296 437 break; 438 + } 439 + telnet_state = TELNET_STATE_CONNECTED; 440 + break; 441 + case TELNET_STATE_IAC_DONT: 442 + switch (b = telnet.read()) { 297 443 default: 298 - TELNET_DEBUG("telnet_read: -> IAC WONT %d\r\n", b); 299 - telnet.printf("%c%c%c", IAC, WONT, b); 444 + TELNET_IAC_DEBUG("telnet_read: IAC DONT %s", 445 + telnet_iac_name(b)); 300 446 break; 301 447 } 302 448 telnet_state = TELNET_STATE_CONNECTED; 303 449 break; 304 450 default: 305 - TELNET_DEBUG("telnet_read: read 0x%x but in state %d\r\n", b, 451 + b = telnet.read(); 452 + TELNET_IAC_DEBUG("telnet_read: read 0x%x but in state %d", b, 306 453 telnet_state); 307 454 break; 308 455 } ··· 314 461 telnet_write(char b) 315 462 { 316 463 /* escape */ 317 - if (settings->telnet && b == IAC) 464 + if (settings->telnet && b == IAC) { 465 + TELNET_DATA_DEBUG("telnet_write: escaped IAC"); 318 466 telnet.write(b); 467 + } 319 468 469 + TELNET_DATA_DEBUG("telnet_write: 0x%x", b); 320 470 return telnet.write(b); 321 471 } 322 472 ··· 327 477 328 478 for (size_t i = 0; i < s.length(); i++) { 329 479 /* escape */ 330 - if (settings->telnet && s.charAt(i) == IAC) 480 + if (settings->telnet && s.charAt(i) == IAC) { 481 + TELNET_DATA_DEBUG("telnet_write: escaped IAC"); 331 482 s2 += IAC; 483 + } 332 484 s2 += s.charAt(i); 485 + TELNET_DATA_DEBUG("telnet_write: 0x%x", s.charAt(i)); 333 486 } 334 487 335 488 return telnet.print(s2);

+3 -1

wifippp.h

··· 26 26 27 27 #define WIFIPPP_VERSION "0.1" 28 28 29 - /* enable various debugging */ 29 + /* enable various debugging through syslog */ 30 30 // #define AT_TRACE 31 31 // #define OUTPUT_TRACE 32 32 // #define PIXEL_TRACE 33 33 // #define PPP_TRACE 34 34 // #define SOCKS_TRACE 35 + // #define TELNET_DATA_TRACE 36 + // #define TELNET_IAC_TRACE 35 37 // #define UPDATE_TRACE 36 38 37 39 #define EEPROM_SIZE 512