<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
</head>
<body text="#000000" bgcolor="#FFFFFF">
I've added an option to send the mongoose debug log output to the
ESP log framework and add a debug log to the if_destroy function.<br>
<br>
There was some talk about not changing the original mongoose files /
maybe doing an OVMS fork, so I won't check the patch in. Diff
attached.<br>
<br>
If you apply the patch: you'll need log level verbose for full debug
details like these:<br>
<br>
<br>
<tt>I (14915) wifi: connected with devolo-f4068d73a03e, channel 11<br>
I (14915) events: Signal(system.wifi.sta.connected)<br>
I (14945) event: sta ip: 192.168.2.101, mask: 255.255.255.0, gw:
192.168.2.1<br>
I (14945) events: Signal(system.wifi.sta.gotip)<br>
I (14945) events: Signal(network.wifi.up)<br>
I (14945) ovms-mdns: Launching MDNS service<br>
I (14955) events: Signal(network.up)<br>
I (14955) esp32wifi: WiFi UP with SSID: devolo-f4068d73a03e, MAC:
30:ae:a4:37:25:88, IP: 192.168.2.101, mask: 255.255.255.0, gw:
192.168.2.1<br>
V (14965) mongoose: mg_socket_if_init 0x3ffb7348 using select()<br>
V (14965) mongoose: mg_mgr_init_opt
==================================<br>
V (14965) mongoose: mg_mgr_init_opt init mgr=0x3ffb7348<br>
I (14965) events: Signal(network.mgr.init)<br>
I (14965) webserver: Launching Web Server<br>
V (14995) mongoose: mg_socket_if_sock_se 0x3ffe068c <b>8192</b><br>
V (14995) mongoose: mg_add_conn 0x3ffb7348 0x3ffe068c<br>
I (14995) telnet: Launching Telnet Server<br>
V (15025) mongoose: mg_socket_if_sock_se 0x3ffe58f0 <b>8193</b><br>
V (15025) mongoose: mg_add_conn 0x3ffb7348 0x3ffe58f0<br>
V (15495) simcom: tx: 41 54 0d
0a | AT.. <br>
D (15495) simcom: tx scmd ch=0 len=4 : AT||<br>
I (15495) simcom: State timeout, transition to 13<br>
I (15495) simcom: State: Enter PoweredOff state<br>
I (17905) wifi: pm start, type:0<br>
</tt><tt><br>
</tt><tt><br>
<i>now doing a HTTP GET /home from the browser</i><i>:</i><br>
<br>
V (35485) mongoose: mg_mgr_handle_conn 0x3ffe068c fd=8192
fd_flags=1 nc_flags=1 rmbl=0 smbl=0<br>
V (35485) mongoose: mg_add_conn 0x3ffb7348 0x3ffe97e0<br>
V (35495) mongoose: mg_if_accept_new_con 0x3ffe068c 0x3ffe97e0 -1
0<br>
V (35495) mongoose: mg_accept_conn 0x3ffe97e0 conn from
192.168.2.103:33574<br>
V (35505) mongoose: mg_socket_if_sock_se 0x3ffe97e0 <b>8194</b><br>
V (35505) mongoose: mg_call 0x3ffe97e0 proto ev=1
ev_data=0x3ffe97f8 flags=0 rmbl=0 smbl=0<br>
V (35505) mongoose: mg_call 0x3ffe97e0 user ev=1
ev_data=0x3ffe97f8 flags=0 rmbl=0 smbl=0<br>
D (35505) webserver: EventHandler: conn=0x3ffe97e0 ev=1
p=0x3ffe97f8<br>
V (35505) mongoose: mg_call 0x3ffe97e0 after user
flags=0 rmbl=0 smbl=0<br>
V (35505) mongoose: mg_call 0x3ffe97e0 after proto
flags=0 rmbl=0 smbl=0<br>
V (35505) mongoose: mg_mgr_handle_conn 0x3ffe068c after fd=8192
nc_flags=1 rmbl=0 smbl=0<br>
V (35505) mongoose: mg_mgr_handle_conn 0x3ffe97e0 fd=8194
fd_flags=1 nc_flags=0 rmbl=0 smbl=0<br>
V (35515) mongoose: mg_handle_tcp_read 0x3ffe97e0 350 bytes
(PLAIN) <- 8194<br>
V (35515) mongoose: mg_recv_common 0x3ffe97e0 350 0<br>
V (35515) mongoose: mg_call 0x3ffe97e0 proto ev=3
ev_data=0x3ffe95d0 flags=0 rmbl=350 smbl=0<br>
V (35515) mongoose: mg_call 0x3ffe97e0 user ev=3
ev_data=0x3ffe95d0 flags=0 rmbl=350 smbl=0<br>
D (35515) webserver: EventHandler: conn=0x3ffe97e0 ev=3
p=0x3ffe95d0<br>
V (35515) mongoose: mg_call 0x3ffe97e0 after user
flags=0 rmbl=350 smbl=0<br>
V (35515) mongoose: mg_http_handler2 0x3ffe97e0
192.168.2.103:33574 <b>GET /home</b><br>
V (35515) mongoose: mg_call 0x3ffe97e0 user ev=102
ev_data=0x3ffe9400 flags=0 rmbl=350 smbl=0<br>
D (35515) webserver: EventHandler: conn=0x3ffe97e0 ev=102
p=0x3ffe9400<br>
V (35515) mongoose: mg_call 0x3ffe97e0 after user
flags=0 rmbl=350 smbl=0<br>
V (35515) mongoose: mg_call 0x3ffe97e0 user ev=100
ev_data=0x3ffe9400 flags=0 rmbl=350 smbl=0<br>
D (35515) webserver: EventHandler: conn=0x3ffe97e0 ev=100
p=0x3ffe9400<br>
<b>I (35515) webserver: HTTP GET /home</b><br>
V (35525) mongoose: mg_call 0x3ffe97e0 after user
flags=0 rmbl=350 smbl=740<br>
V (35525) mongoose: mg_call 0x3ffe97e0 after proto
flags=0 rmbl=0 smbl=740<br>
V (35525) mongoose: mg_mgr_handle_conn 0x3ffe97e0 after fd=8194
nc_flags=0 rmbl=0 smbl=740<br>
V (35525) mongoose: mg_mgr_handle_conn 0x3ffe97e0 fd=8194
fd_flags=2 nc_flags=0 rmbl=0 smbl=740<br>
V (35525) mongoose: mg_write_to_socket 0x3ffe97e0 740 bytes
-> 8194<br>
V (35525) mongoose: mg_if_sent_cb 0x3ffe97e0 740<br>
V (35525) mongoose: mg_call 0x3ffe97e0 proto ev=4
ev_data=0x3ffe95e0 flags=0 rmbl=0 smbl=0<br>
V (35525) mongoose: mg_call 0x3ffe97e0 user ev=4
ev_data=0x3ffe95e0 flags=0 rmbl=0 smbl=0<br>
D (35525) webserver: EventHandler: conn=0x3ffe97e0 ev=4
p=0x3ffe95e0<br>
V (35525) mongoose: mg_call 0x3ffe97e0 after user
flags=0 rmbl=0 smbl=0<br>
V (35525) mongoose: mg_call 0x3ffe97e0 after proto
flags=0 rmbl=0 smbl=0<br>
V (35525) mongoose: mg_mgr_handle_conn 0x3ffe97e0 after fd=8194
nc_flags=0 rmbl=0 smbl=0<br>
</tt><tt><br>
<br>
<br>
</tt><b><tt>OVMS > wifi mode off</tt></b><tt><br>
Stopping wifi station...<br>
I (41145) events: Signal(system.wifi.down)<br>
I (41145) events: Signal(network.wifi.down)<br>
I (41145) events: Signal(network.reconfigured)<br>
I (41145) events: Signal(network.down)<br>
I (41155) wifi: state: run -> init (0)<br>
I (41155) wifi: pm stop, total sleep time: 0/23262330<br>
I (41155) wifi: n:11 0, o:11 2, ap:255 255, sta:11 2, prof:1<br>
I (41165) wifi: flush txq<br>
I (41165) wifi: stop sw txq<br>
I (41165) wifi: lmac stop hw txq<br>
I (41165) wifi: Deinit lldesc rx mblock:4<br>
I (41165) events: Signal(system.wifi.sta.disconnected)<br>
I (41175) events: Signal(system.wifi.sta.stop)<br>
I (41525) events: Signal(network.mgr.stop)<br>
I (41525) webserver: Stopping Web Server<br>
I (41525) telnet: Stopping Telnet Server<br>
V (41535) mongoose: mg_mgr_free 0x3ffb7348<br>
V (41535) mongoose: mg_close_conn 0x3ffe97e0 0 <b>8194</b><br>
V (41535) mongoose: mg_socket_if_destroy nc=0x3ffe97e0 sock=8194
flags=0<br>
V (41545) mongoose: mg_call 0x3ffe97e0 proto ev=5
ev_data=0x0 flags=0 rmbl=0 smbl=0<br>
V (41545) mongoose: mg_call 0x3ffe97e0 user ev=5
ev_data=0x0 flags=0 rmbl=0 smbl=0<br>
D (41545) webserver: EventHandler: conn=0x3ffe97e0 ev=5 p=0x0<br>
V (41545) mongoose: mg_call 0x3ffe97e0 after user
flags=0 rmbl=0 smbl=0<br>
V (41545) mongoose: mg_call 0x3ffe97e0 after proto
flags=0 rmbl=0 smbl=0<br>
V (41545) mongoose: mg_close_conn 0x3ffe58f0 1 <b>8193</b><br>
V (41545) mongoose: mg_socket_if_destroy nc=0x3ffe58f0 sock=8193
flags=1<br>
V (41555) mongoose: mg_call 0x3ffe58f0 user ev=5
ev_data=0x0 flags=1 rmbl=0 smbl=0<br>
V (41555) mongoose: mg_call 0x3ffe58f0 after user
flags=1 rmbl=0 smbl=0<br>
V (41555) mongoose: mg_close_conn 0x3ffe068c 1 <b>8192</b><br>
V (41555) mongoose: mg_socket_if_destroy nc=0x3ffe068c sock=8192
flags=1<br>
V (41565) mongoose: mg_call 0x3ffe068c proto ev=5
ev_data=0x0 flags=1 rmbl=0 smbl=0<br>
V (41565) mongoose: mg_call 0x3ffe068c user ev=5
ev_data=0x0 flags=1 rmbl=0 smbl=0<br>
D (41565) webserver: EventHandler: conn=0x3ffe068c ev=5 p=0x0<br>
V (41565) mongoose: mg_call 0x3ffe068c after user
flags=1 rmbl=0 smbl=0<br>
V (41565) mongoose: mg_call 0x3ffe068c after proto
flags=1 rmbl=0 smbl=0<br>
</tt><tt><br>
<br>
</tt>… doesn't look wrong so far, socket get closed correctly.
mg_socket_if_destroy calls closesocket = lwip_close_r, so everything
_should_ be ok… but…<br>
<br>
<tt><br>
</tt><tt></tt><b><tt>OVMS > wifi mode client </tt></b><tt><br>
Starting WIFI as a client for any defined SSID<br>
I (47225) wifi: wifi firmware version: 403db1d<br>
I (47225) wifi: config NVS flash: enabled<br>
I (47225) wifi: config nano formating: disabled<br>
I (47225) system_api: Base MAC address is not set, read default
base MAC address from BLK0 of EFUSE<br>
I (47225) system_api: Base MAC address is not set, read default
base MAC address from BLK0 of EFUSE<br>
I (47245) wifi: Init dynamic tx buffer num: 16<br>
I (47245) wifi: Init data frame dynamic rx buffer num: 16<br>
I (47245) wifi: Init management frame dynamic rx buffer num: 16<br>
I (47245) wifi: wifi driver task: 3ffe251c, prio:23, stack:4096<br>
I (47245) wifi: Init static rx buffer num: 4<br>
I (47245) wifi: Init dynamic rx buffer num: 16<br>
I (47245) wifi: wifi power manager task: 0x3ffe5a9c prio: 21
stack: 2560<br>
I (47255) wifi: mode : sta (30:ae:a4:37:25:88)<br>
I (47255) events: Signal(system.wifi.sta.start)<br>
W (50495) wifi: incorrect scan type: 1073541416<br>
I (52905) events: Signal(system.wifi.scan.done)<br>
I (52905) esp32wifi: Found SSID devolo-f4068d73a03e - trying to
connect<br>
I (54235) wifi: n:11 2, o:1 0, ap:255 255, sta:11 2, prof:1<br>
I (54885) wifi: state: init -> auth (b0)<br>
I (54895) wifi: state: auth -> assoc (0)<br>
I (54905) wifi: state: assoc -> run (10)<br>
I (54915) wifi: connected with devolo-f4068d73a03e, channel 11<br>
I (54915) events: Signal(system.wifi.sta.connected)<br>
I (54945) event: sta ip: 192.168.2.101, mask: 255.255.255.0, gw:
192.168.2.1<br>
I (54955) events: Signal(system.wifi.sta.gotip)<br>
I (54955) events: Signal(network.wifi.up)<br>
I (54955) ovms-mdns: Launching MDNS service<br>
I (54955) events: Signal(network.up)<br>
I (54965) esp32wifi: WiFi UP with SSID: devolo-f4068d73a03e, MAC:
30:ae:a4:37:25:88, IP: 192.168.2.101, mask: 255.255.255.0, gw:
192.168.2.1<br>
V (54965) mongoose: mg_socket_if_init 0x3ffb7348 using select()<br>
V (54965) mongoose: mg_mgr_init_opt
==================================<br>
V (54965) mongoose: mg_mgr_init_opt init mgr=0x3ffb7348<br>
I (54965) events: Signal(network.mgr.init)<br>
I (54965) webserver: Launching Web Server<br>
<font color="#ff0000"><b>V (54995) mongoose: mg_bind_opt
Failed to open listener: 112</b></font><br>
V (54995) mongoose: mg_socket_if_destroy nc=0x3ffe996c sock=-1
flags=1<br>
E (54995) webserver: Cannot bind to port 80: failed to open
listener<br>
I (54995) telnet: Launching Telnet Server<br>
V (55025) mongoose: mg_socket_if_sock_se 0x3ffe98c8 8196<br>
V (55025) mongoose: mg_add_conn 0x3ffb7348 0x3ffe98c8<br>
I (57905) wifi: pm start, type:0<br>
</tt><br>
<br>
… so it's indeed 112 = EADDRINUSE as assumed.<br>
<br>
As mongoose does everything right, this seems to be an LWIP issue?
Mark, Steve?<br>
<br>
<br>
<div class="moz-cite-prefix">Am 29.01.2018 um 14:17 schrieb Mark
Webb-Johnson:<br>
</div>
<blockquote type="cite"
cite="mid:4EB32735-789A-4781-9A59-5698425186EB@webb-johnson.net">
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
The bind has to occur in the network.mgr.init handler. That is the
point between mg_mgr_init and mg_mgr_poll.
<div class=""><br class="">
</div>
<div class="">Perhaps in the handler we can check m_connected_wifi
and only bind if wifi is up? But would also need to
pickup network.reconfigured and check m_connected_wifi there as
well.</div>
</blockquote>
<br>
The webserver NetManInit function is already triggered on
network.mgr.init and checks m_connected_wifi.<br>
<br>
Regards,<br>
Michael<br>
<br>
<br>
<blockquote type="cite"
cite="mid:4EB32735-789A-4781-9A59-5698425186EB@webb-johnson.net">
<div class="">
<div class=""><br class="">
</div>
<div class="">Regards, Mark.<br class="">
<div class="">
<div class=""><br class="">
</div>
<div class="">
<div>
<blockquote type="cite" class="">
<div class="">On 29 Jan 2018, at 6:11 PM, Michael
Balzer <<a href="mailto:dexter@expeedo.de"
class="" moz-do-not-send="true">dexter@expeedo.de</a>>
wrote:</div>
<br class="Apple-interchange-newline">
<div class="">
<meta http-equiv="Content-Type" content="text/html;
charset=utf-8" class="">
<div text="#000000" bgcolor="#FFFFFF" class="">
<div class="moz-cite-prefix">mg_bind() fails with
"failed to open listener". I haven't traced it
further yet, assumed it's the bind() that fails.<br
class="">
<br class="">
Mongoose (now?) uses the standard socket API, so
does not need to handle LWIP details, or does
it?<br class="">
<br class="">
I can do some more debugging to get the exact
point of failure.<br class="">
<br class="">
Regards,<br class="">
Michael<br class="">
<br class="">
<br class="">
Am 29.01.2018 um 02:28 schrieb Stephen Casner:<br
class="">
</div>
<blockquote type="cite"
cite="mid:alpine.OSX.2.21.1801281721340.55836@auge.attlocal.net"
class="">
<pre class="" wrap="">Mark,
Back in November we discussed this problem of the client's half of the
connection being left open. Then as now, you commented that mongoose
sends a close event (MG_EV_CLOSE) for each open connection when the
interface went down.
It does send a close event, but not until after the wifi is already
shut down so closing the socket at that point does not send any packet
to the client. I decided to punt on that issue, though, because
manually shutting down wifi is not an important use case. The more
likely case is that wifi connectivity is lost due to motion or other
causes and in that case no close packet can be delivered anyway.
I interpreted Michael's message to be referring to a problem with
ports on the server (OVMS) end. That is, to say that mongoose didn't
clean up LWIP state properly. Michael, can you explain a bit more?
-- Steve
On Mon, 29 Jan 2018, Mark Webb-Johnson wrote:
</pre>
<blockquote type="cite" class="">
<pre class="" wrap="">I suspect that this is timing related:
OVMS > wifi mode client XXX
Starting WIFI as a client to XXX…
…
I (337100) ssh: Launching SSH Server
V (338830) ssh: Event MG_EV_ACCEPT conn 0x3ffee8b4, data 0x3ffee8cc
V (338840) ssh: Event MG_EV_RECV conn 0x3ffee8b4, data received 21
V (338840) ssh: Event MG_EV_SEND conn 0x3ffee8b4, data 0x3ffe5d90
V (338840) ssh: Event MG_EV_RECV conn 0x3ffee8b4, data received 1024
V (338850) ssh: Event MG_EV_RECV conn 0x3ffee8b4, data received 408
…
OVMS > wifi mode off
Stopping wifi station...
I (350580) ovms-mdns: Stopping MDNS service
I (350580) wifi: state: run -> init (0)
I (350590) wifi: pm stop, total sleep time: 0/11930449
I (350590) wifi: n:11 0, o:11 0, ap:255 255, sta:11 0, prof:1
I (350600) wifi: flush txq
I (350600) wifi: stop sw txq
I (350600) wifi: lmac stop hw txq
I (350600) wifi: Deinit lldesc rx mblock:4
I (351340) webserver: Stopping Web Server
I (351340) ssh: Stopping SSH Server
V (351540) ssh: Event MG_EV_CLOSE conn 0x3ffee8b4, data 0x0
V (351540) ssh: Event MG_EV_CLOSE conn 0x3ffeb468, data 0x0
I (357570) event: station ip lost
But ssh client connection is still up on my workstation. Looks like
the MG_EV_CLOSE events came in after the SSH server was stopped.
I repeated the test, but with event logging on:
OVMS > wifi mode off
Stopping wifi station...
I (34171) events: Signal(system.wifi.down)
I (34171) events: Signal(network.wifi.down)
I (34171) ovms-mdns: Stopping MDNS service
I (34171) events: Signal(network.reconfigured)
I (34171) events: Signal(network.down)
I (34171) wifi: state: run -> init (0)
I (34181) wifi: pm stop, total sleep time: 0/9603569
I (34181) wifi: n:11 0, o:11 0, ap:255 255, sta:11 0, prof:1
I (34191) wifi: flush txq
I (34191) wifi: stop sw txq
I (34191) wifi: lmac stop hw txq
I (34191) wifi: Deinit lldesc rx mblock:4
I (34191) events: Signal(system.wifi.sta.disconnected)
I (34191) events: Signal(system.wifi.sta.stop)
I (35131) events: Signal(network.mgr.stop)
I (35131) webserver: Stopping Web Server
I (35131) ssh: Stopping SSH Server
V (35331) ssh: Event MG_EV_CLOSE conn 0x3ffec138, data 0x0
V (35331) ssh: Event MG_EV_CLOSE conn 0x3ffeb768, data 0x0
MDNS exits quicker because it responds to the network.wifi.down message, while ssh uses the network.mgr.stop event. In a clean shutdown there is a difference.
Perhaps we should issue network.mgr.stop earlier? However, even if we close the connections from our end, I’m not sure if the packet would make it through to the other end before the wifi disconnects.
Regards, Mark.
</pre>
<blockquote type="cite" class="">
<pre class="" wrap="">On 29 Jan 2018, at 2:13 AM, Stephen Casner <a class="moz-txt-link-rfc2396E" href="mailto:casner@acm.org" moz-do-not-send="true"><casner@acm.org></a> wrote:
I handled wifi shutdowns cleanly when I first implemented telnet and
ssh as their own tasks. Now that they are under Mongoose, it is out
of my control. The socket is owned by the Mongoose code.
-- Steve
On Sun, 28 Jan 2018, Michael Balzer wrote:
</pre>
<blockquote type="cite" class="">
<pre class="" wrap="">I've begun working on the webserver and noticed something that may
be correlated to this: sockets don't get closed when losing the
connection. The effect is visible on both web and telnet server (ssh
not tested). To reproduce, switch the Wifi network with an open
connection, the port will not be available until timeout.
Regards,
Michael</pre>
<br class="">
<fieldset class="mimeAttachmentHeader"></fieldset>
<br class="">
<pre class="" wrap="">_______________________________________________
OvmsDev mailing list
<a class="moz-txt-link-abbreviated" href="mailto:OvmsDev@lists.teslaclub.hk" moz-do-not-send="true">OvmsDev@lists.teslaclub.hk</a>
<a class="moz-txt-link-freetext" href="http://lists.teslaclub.hk/mailman/listinfo/ovmsdev" moz-do-not-send="true">http://lists.teslaclub.hk/mailman/listinfo/ovmsdev</a>
</pre>
</blockquote>
</blockquote>
</blockquote>
</blockquote>
<br class="">
<br class="">
<pre class="moz-signature" cols="144">--
Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
</pre>
</div>
_______________________________________________<br
class="">
OvmsDev mailing list<br class="">
<a href="mailto:OvmsDev@lists.teslaclub.hk" class=""
moz-do-not-send="true">OvmsDev@lists.teslaclub.hk</a><br
class="">
<a class="moz-txt-link-freetext" href="http://lists.teslaclub.hk/mailman/listinfo/ovmsdev">http://lists.teslaclub.hk/mailman/listinfo/ovmsdev</a><br
class="">
</div>
</blockquote>
</div>
<br class="">
</div>
</div>
</div>
</div>
<br>
<fieldset class="mimeAttachmentHeader"></fieldset>
<br>
<pre wrap="">_______________________________________________
OvmsDev mailing list
<a class="moz-txt-link-abbreviated" href="mailto:OvmsDev@lists.teslaclub.hk">OvmsDev@lists.teslaclub.hk</a>
<a class="moz-txt-link-freetext" href="http://lists.teslaclub.hk/mailman/listinfo/ovmsdev">http://lists.teslaclub.hk/mailman/listinfo/ovmsdev</a>
</pre>
</blockquote>
<br>
<pre class="moz-signature" cols="160">--
Michael Balzer * Helkenberger Weg 9 * D-58256 Ennepetal
Fon 02333 / 833 5735 * Handy 0176 / 206 989 26
</pre>
</body>
</html>