ofekp/TinyUPnP

Invalid router info

taxilly opened this issue · 10 comments

taxilly commented

Been trying to get this to work using an Wemos D1 Mini (ESP8266), IGD connection goes well then drops the ball and TCP connection times out. Using latest master (cd9771c)

21:01:38.043 -> [INFO] MDNS setup is successful!
21:01:38.077 -> [INFO] Http Station server started
21:01:38.110 -> Testing WiFi connection for [192.168.0.134] ==> GOOD
21:01:38.178 -> Testing internet connection ==> GOOD
21:01:38.760 -> isGatewayInfoValid [(IP unset)] port [0] path [] actionPort [0] actionPath [] serviceTypeName []
21:01:38.861 -> Gateway info is not valid
21:01:38.895 -> 
21:01:38.895 -> Sending M-SEARCH to [239.255.255.250] Port [1900]
21:01:38.930 -> M-SEARCH * HTTP/1.1
21:01:38.964 -> HOST: 239.255.255.250:1900
21:01:38.997 -> MAN: "ssdp:discover"
21:01:39.031 -> MX: 5
21:01:39.031 -> ST: urn:schemas-upnp-org:device:InternetGatewayDevice:1
21:01:39.102 -> 
21:01:39.102 -> 
21:01:39.102 -> M-SEARCH sent
21:01:39.102 -> Received packet of size [443] ip [192.168.0.1] port [1900]
21:01:39.169 -> UDP packet read bytes [443] out of [443]
21:01:39.202 -> Gateway packet content:
21:01:39.240 -> HTTP/1.1 200 OK
21:01:39.273 -> CACHE-CONTROL: max-age=3600
21:01:39.307 -> ST: urn:schemas-upnp-org:device:InternetGatewayDevice:1
21:01:39.307 -> USN: uuid:30343438-3030-3000-0000-1835d1a8dec5::urn:schemas-upnp-org:device:InternetGatewayDevice:1
21:01:39.446 -> EXT:
21:01:39.446 -> SERVER: RedHatEnterpriseServer/6.10 UPnP/1.1 MiniUPnPd/1.9
21:01:39.512 -> LOCATION: http://192.168.0.1:5000/rootDesc.xml
21:01:39.546 -> OPT: "http://schemas.upnp.org/upnp/1/0/"; ns=01
21:01:39.613 -> 01-NLS: 1585848159
21:01:39.613 -> BOOTID.UPNP.ORG: 1585848159
21:01:39.646 -> CONFIGID.UPNP.ORG: 1337
21:01:39.680 -> 
21:01:39.680 -> 
21:01:39.680 -> INTERNET_GATEWAY_DEVICE found
21:01:39.713 -> IGD location found [http://192.168.0.1:5000/rootDesc.xml]
21:01:39.782 -> 192.168.0.1
21:01:39.782 -> 5000
21:01:39.819 -> /rootDesc.xml
21:01:39.819 -> Connecting to IGD with host [192.168.0.1] port [5000]
21:01:39.961 -> Connected to IGD
21:01:39.961 -> called getIGDEventURLs
21:01:39.995 -> deviceInfo->actionPath [] deviceInfo->path [/rootDesc.xml]
21:01:40.195 -> HTTP/1.1 200 OK
21:01:40.195 -> Content-Type: text/xml; charset="utf-8"
21:01:40.228 -> Connection: close
21:01:40.261 -> Content-Length: 2619
21:01:40.261 -> Server: RedHatEnterpriseServer/6.10 UPnP/1.1 MiniUPnPd/1.9
21:01:40.330 -> Ext:
21:01:40.330 -> 
21:01:40.330 -> <?xml version="1.0"?>
21:01:45.280 -> <root xmlns="urn:schemas-upnp-org:device-1-0" configId="1337"><specVersion><major>1</major><minor>1</minor></specVersion><device><deviceType>urn:schemas-upnp-org:device:InternetGatewayDevice:1</deviceType><friendlyName>ARRIS TG2492LG-85 Router</friendlyName><manufacturer>ARRIS</manufacturer><manufacturerURL>http://www.arrisi.com/</manufacturerURL><modelDescription>ARRIS TG2492LG-85 Router</modelDescription><modelName>ARRIS TG2492LG-85 Router</modelName><modelNumber>4.5.5.44_0410</modelNumber><modelURL>http://www.arrisi.com/</modelURL><serialNumber>AAAP90448000</serialNumber><UDN>uuid:30343438-3030-3000-0000-1835d1a8dec5</UDN><serviceList><service><serviceType>urn:schemas-upnp-org:service:Layer3Forwarding:1</serviceType><serviceId>urn:upnp-org:serviceId:L3Forwarding1</serviceId><SCPDURL>/L3F.xml</SCPDURL><controlURL>/ctl/L3F</controlURL><eventSubURL>/evt/L3F</eventSubURL></service></serviceList><deviceList><device><deviceType>urn:schemas-upnp-org:device:WANDevice:1</deviceType><friendlyName>WANDevice</friendlyName><manufacturer>ARRIS</manufacturer><manufacturerURL>http://www.arrisi.com/</manufacturerURL><modelDescription>WANDevice</modelDescription><modelName>WANDevice</modelName><modelNumber>20190410</modelNumber><modelURL>http://www.arrisi.com/</modelURL><serialNumber>AAAP90448000</serialNumber><UDN>uuid:30343438-3030-3000-0000-1835d1a8dec6</UDN><UPC>TG2492LG-85</UPC><serviceList><service><serviceType>urn:schemas-upnp-org:service:WANCommonInterfaceConfig:1</serviceType><serviceId>urn:upnp-org:serviceId:WANCommonIFC1</serviceId><SCPDURL>/WANCfg.xml</SCPDURL><controlURL>/ctl/CmnIfCfg</controlURL><eventSubURL>/evt/CmnIfCfg</eventSubURL></service></serviceList><deviceList><device><deviceType>urn:schemas-upnp-org:device:WANConnectionDevice:1</deviceType><friendlyName>WANConnectionDevice</friendlyName><manufacturer>ARRIS</manufacturer><manufacturerURL>http://www.arrisi.com/</manufacturerURL><modelDescription>Residential Gateway</modelDescription><modelName>TG2492LG-85</modelName><modelNumber>20190410</modelNumber><modelURL>http://www.arrisi.com/</modelURL><serialNumber>AAAP90448000</serialNumber><UDN>uuid:30343438-3030-3000-0000-1835d1a8dec7</UDN><UPC>TG2492LG-85</UPC><serviceList><service><serviceType>urn:schemas-upnp-org:service:WANIPConnection:1</serviceType><serviceId>urn:upnp-org:serviceId:WANIPConn1</serviceId><SCPDURL>/WANIPCn.xml</SCPDURL><controlURL>/ctl/IPConn</controlURL><eventSubURL>/evt/IPConn</eventSubURL></service></serviceList></device></deviceList></device></deviceList><presentationURL>http://192.168.0.1/</presentationURL></device></root>called getIGDEventURLs
21:01:48.370 -> deviceInfo->actionPath [] deviceInfo->path [/rootDesc.xml]
21:01:54.370 -> TCP connection timeout while executing getIGDEventURLs
21:01:54.849 -> called getIGDEventURLs
21:01:54.849 -> deviceInfo->actionPath [] deviceInfo->path [/rootDesc.xml]
21:02:00.846 -> TCP connection timeout while executing getIGDEventURLs
21:02:00.879 -> Timeout expired while adding a new port mapping
21:02:00.947 -> ERROR: Invalid router info, cannot continue
21:02:00.981 ->

Any help is appreciated :)

ofekp commented

I added few more logs, can you please run again with branch #60

You'll have to replace the code in your library to get this to use the new code.

Please attach logs as text files. Thanks.

taxilly commented

Thanks for the quick response - here's the log:

log.txt

ofekp commented

Are you sure you're using the code from the branch? This makes no sense.
Can you verify by inserting an error and making sure the compilation fails? Or adding a log line or something please? Thanks

Also, can you try to increase the timeout to 30000? It looks like this:
https://github.com/ofekp/TinyUPnP/blob/master/examples/SimpleServerEsp32/SimpleServerEsp32.ino#L23

taxilly commented

Ah, my bad - here's the correct log @ofekp

log.txt

Most of the time the program crashes from a soft WDT reset, stack trace:


Decoding stack results
0x40211085: uart_write(uart_t*, char const*, size_t) at /Users/cass/Library/Arduino15/packages/esp8266/hardware/esp8266/2.6.3/cores/esp8266/uart.cpp line 509
0x40100452: millis() at /Users/cass/Library/Arduino15/packages/esp8266/hardware/esp8266/2.6.3/cores/esp8266/core_esp8266_wiring.cpp line 188
0x4020e3e8: HardwareSerial::write(unsigned char const*, unsigned int) at /Users/cass/Library/Arduino15/packages/esp8266/hardware/esp8266/2.6.3/cores/esp8266/HardwareSerial.h line 165
0x4020e895: Print::print(String const&) at /Users/cass/Library/Arduino15/packages/esp8266/hardware/esp8266/2.6.3/cores/esp8266/Print.cpp line 126
0x4020db03: TinyUPnP::getIGDEventURLs(_gatewayInfo*) at /Users/cass/Documents/Arduino/libraries/TinyUPnP/src/TinyUPnP.cpp line 708
0x40211ac8: UdpContext::unref() at /Users/cass/Library/Arduino15/packages/esp8266/hardware/esp8266/2.6.3/libraries/ESP8266WiFi/src/include/UdpContext.h line 91
0x402107e5: __delay(unsigned long) at /Users/cass/Library/Arduino15/packages/esp8266/hardware/esp8266/2.6.3/cores/esp8266/core_esp8266_wiring.cpp line 57
0x4020df67: TinyUPnP::getGatewayInfo(_gatewayInfo*, long) at /Users/cass/Documents/Arduino/libraries/TinyUPnP/src/TinyUPnP.cpp line 212
0x4020e092: TinyUPnP::commitPortMappings() at /Users/cass/Documents/Arduino/libraries/TinyUPnP/src/TinyUPnP.cpp line 98
0x4020f091: String::invalidate() at /Users/cass/Library/Arduino15/packages/esp8266/hardware/esp8266/2.6.3/cores/esp8266/WString.cpp line 140
0x40201480: initUPnP() at /Users/cass/Code/Projects/Sites/hydroponics/hardware/wemos_2/sketch_apr04a/sketch_apr04a.ino line 296
0x40203dfe: setup() at /Users/cass/Code/Projects/Sites/hydroponics/hardware/wemos_2/sketch_apr04a/sketch_apr04a.ino line 56
0x402102e4: loop_wrapper() at /Users/cass/Library/Arduino15/packages/esp8266/hardware/esp8266/2.6.3/cores/esp8266/core_esp8266_main.cpp line 177
taxilly commented

Tried it with a different D1 Mini, port listing seems to have been set at some point - but soft reset happens 90% of the time
log2.txt

taxilly commented

From my cursory testing and messing about with trying to fix the soft WDT reset I think I have found the cause -- debugPrint(line); in getIGDEventURLs takes so long to be printed to serial monitor that the watchdog timer isn't reset in time causing the D1 Mini to reset.

Commenting out this line stops this behaviour, obviously.

  • 👍1
ofekp commented

Looks like your router is not splitting the XML to multiple lines, it sends the response with a somewhat large XML file back in one line.
Multiple options here (I would try both in this order):

  1. disable the debug print you have found
  2. disable debug logs entirely by commenting out this line

You can make sure your router accepted the new rule using the UI page or using upnpc in linux.
Please give it a try.

ofekp commented

Hey, does this work for you?
Let me know if we can close this please,
Thanks.

taxilly commented

Yeah sorry for inactivity, commenting the line fixes it.

  • ❤️1
ofekp commented

@taxilly Thank you.