Hi Jussi,

I saw your patch got accepted about the same time you sent it to the mailinglist, so did not test it during that time, since someone else obviously did that.

Now I have had devices running for a while but unfortunately openvpn does not reconnect automatically, I double checked so the settings were not changed by some unknown reason. 

We run over cellular and I will provide some chunks of the log. Its a mixture of ofono and connman logs, but that might be helpful to see the timing.

If this gets to verbose please let me know if you want to discuss further off list.

The device connects to the cellular network and the vpn goes up:

08:19:17 debug ofonod[532]: ../git/src/gprs.c:ofono_gprs_status_notify() /ublox_0 status roaming (5)
08:19:17 debug ofonod[532]: ../git/src/gprs.c:gprs_attached_update() 0x22aec78, attached: 1, gprs->attached: 0
08:19:17 debug ofonod[532]: ../git/src/gprs.c:gprs_set_attached_property() 0x22aec78 0 -> 1
08:19:17 debug ofonod[532]: ../git/drivers/ubloxmodem/network-registration.c:ctze_notify() tz +04 dst 0 time 20/03/14,09:19:39
08:19:17 debug ofonod[532]: ../git/src/network.c:ofono_netreg_time_notify() net time 2020-03-14 09:19:39 utcoff 3600 dst 0
08:19:17 warn connmand[474]: ipconfig state 2 ipconfig method 1
08:19:17 debug ofonod[532]: ../git/drivers/ubloxmodem/gprs-context.c:ublox_gprs_activate_primary() cid 1
08:19:17 debug ofonod[532]: ../git/src/network.c:ofono_netreg_status_notify() /ublox_0 status 5 tech 2 lac 20201 ci 8577130
08:19:17 debug ofonod[532]: ../git/src/gprs.c:netreg_status_changed() 5 (roaming)
08:19:17 debug ofonod[532]: ../git/src/gprs.c:gprs_netreg_update() attach: 1, driver_attached: 1
08:19:17 debug ofonod[532]: ../git/drivers/ubloxmodem/gprs-context.c:cgdcont_cb() ok 1
08:19:17 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:cops_numeric_cb() Cops numeric got mcc: XXX, mnc: XX
08:19:17 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:csq_cb() csq_cb: 29
08:19:17 debug ofonod[532]: ../git/src/network.c:ofono_netreg_strength_notify() strength 93
08:19:20 debug ofonod[532]: ../git/drivers/ubloxmodem/gprs-context.c:cgact_enable_cb() ok 1
08:19:20 debug ofonod[532]: ../git/src/modem.c:get_modem_property() modem 0x22aec00 property NetworkInterface
08:19:20 debug ofonod[532]: ../git/src/gprs.c:pri_activate_callback() 0x22b9b68
08:19:20 info connman-vpnd[481]: usb0 {update} flags 69699 <UP,RUNNING,LOWER_UP>
08:19:20 info connman-vpnd[481]: usb0 {newlink} index 7 address 02:07:01:18:00:0B mtu 1400
08:19:20 info connman-vpnd[481]: usb0 {newlink} index 7 operstate 0 <UNKNOWN>
08:19:20 info connmand[474]: usb0 {update} flags 69699 <UP,RUNNING,LOWER_UP>
08:19:20 info connmand[474]: usb0 {newlink} index 7 address 02:07:01:18:00:0B mtu 1400
08:19:20 info connmand[474]: usb0 {newlink} index 7 operstate 0 <UNKNOWN>
08:19:20 info connmand[474]: usb0 {add} route ff00:: gw :: scope 0 <UNIVERSE>
08:19:20 info connmand[474]: usb0 {add} route fe80:: gw :: scope 0 <UNIVERSE>
08:19:20 warn connmand[474]: ipconfig state 3 ipconfig method 1
08:19:20 info connmand[474]: Setting hostname to <hostname>
08:19:20 info connmand[474]: usb0 {del} route fe80:: gw :: scope 0 <UNIVERSE>
08:19:20 info connmand[474]: usb0 {del} route ff00:: gw :: scope 0 <UNIVERSE>
08:19:20 info connmand[474]: usb0 {add} address 192.168.1.100/24 label usb0 family 2
08:19:20 info connmand[474]: usb0 {add} route 192.168.1.0 gw 0.0.0.0 scope 253 <LINK>
08:19:20 info connmand[474]: usb0 {add} route 192.168.1.1 gw 0.0.0.0 scope 253 <LINK>
08:19:20 info connmand[474]: usb0 {add} route 0.0.0.0 gw 192.168.1.1 scope 0 <UNIVERSE>
08:19:20 warn connmand[474]: ipconfig state 2 ipconfig method 1
08:19:20 info connmand[474]: vpn0 {create} index 8 type 65534 <NONE>
08:19:20 info connmand[474]: vpn0 {update} flags 4240 <DOWN>
08:19:20 info connmand[474]: vpn0 {newlink} index 8 address 00:00:00:00:00:00 mtu 1500
08:19:20 info connmand[474]: vpn0 {newlink} index 8 operstate 2 <DOWN>
08:19:20 debug ofonod[532]: ../git/plugins/udevng.c:add_serial_device() Device is missing required OFONO_DRIVER property
08:19:20 info connman-vpnd[481]: vpn0 {create} index 8 type 65534 <NONE>
08:19:20 info connman-vpnd[481]: vpn0 {update} flags 4240 <DOWN>
08:19:20 info connman-vpnd[481]: vpn0 {newlink} index 8 operstate 2 <DOWN>
08:19:20 warn connmand[474]: ipconfig state 2 ipconfig method 1
08:19:20 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:cops_cb() cops_cb: Oper, XXX XX 2
08:19:20 debug ofonod[532]: ../git/src/network.c:current_operator_callback() 0x22b2ed8, (nil)
08:19:20 debug ofonod[532]: ../git/src/gprs.c:netreg_status_changed() 5 (roaming)
08:19:20 debug ofonod[532]: ../git/src/gprs.c:gprs_netreg_update() attach: 1, driver_attached: 1
08:19:20 info connmand[474]: usb0 {add} route 212.227.81.55 gw 192.168.1.1 scope 0 <UNIVERSE>
08:19:20 debug ofonod[532]: ../git/src/network.c:ofono_netreg_status_notify() /ublox_0 status 5 tech 2 lac 0 ci 16
08:19:20 debug ofonod[532]: ../git/src/gprs.c:netreg_status_changed() 5 (roaming)
08:19:20 debug ofonod[532]: ../git/src/gprs.c:gprs_netreg_update() attach: 1, driver_attached: 1
08:19:20 debug ofonod[532]: ../git/drivers/atmodem/gprs.c:at_cgdcont_read_cb() ok 1
08:19:20 debug ofonod[532]: ../git/src/gprs.c:ofono_gprs_cid_activated() cid 1
08:19:20 debug ofonod[532]: ../git/src/gprs.c:ofono_gprs_cid_activated() cid 1 already activated
08:19:20 warn connman-vpnd[481]: Connected management socket
08:19:20 warn connman-vpnd[481]: openvpn request >INFO:OpenVPN Management Interface Version 1 -- type 'help' for more info^M
08:19:20 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:cops_numeric_cb() Cops numeric got mcc: XXX, mnc: XX
08:19:20 info connmand[474]: usb0 {del} route 212.227.81.55 gw 192.168.1.1 scope 0 <UNIVERSE>
08:19:20 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:csq_cb() csq_cb: 30
08:19:20 debug ofonod[532]: ../git/src/network.c:ofono_netreg_strength_notify() strength 96
08:19:20 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:cops_cb() cops_cb: Oper, XXX XX 2
08:19:20 debug ofonod[532]: ../git/src/network.c:current_operator_callback() 0x22b2ed8, 0x22b8888
08:19:22 debug ofonod[532]: ../git/plugins/udevng.c:check_modem_list()
08:19:25 info connman-vpnd[481]: vpn0 {newlink} index 8 operstate 2 <DOWN>
08:19:25 info connmand[474]: vpn0 {newlink} index 8 address 00:00:00:00:00:00 mtu 1500
08:19:25 info connmand[474]: vpn0 {newlink} index 8 operstate 2 <DOWN>
08:19:25 info connman-vpnd[481]: vpn0 {update} flags 102609 <UP,RUNNING,LOWER_UP>
08:19:25 info connman-vpnd[481]: vpn0 {newlink} index 8 operstate 6 <UP>
08:19:25 info connmand[474]: vpn0 {update} flags 102609 <UP,RUNNING,LOWER_UP>
08:19:25 info connmand[474]: vpn0 {newlink} index 8 address 00:00:00:00:00:00 mtu 1500
08:19:25 info connmand[474]: vpn0 {newlink} index 8 operstate 6 <UP>
08:19:25 info connmand[474]: vpn0 {add} route ff00:: gw :: scope 0 <UNIVERSE>
08:19:25 info connmand[474]: vpn0 {add} route fe80:: gw :: scope 0 <UNIVERSE>
08:19:25 info connmand[474]: vpn0 {add} address 10.129.36.7/16 label vpn0 family 2
08:19:25 info connmand[474]: vpn0 {add} route 10.129.0.0 gw 0.0.0.0 scope 253 <LINK>
08:19:25 info connmand[474]: rp_filter set to 2 (loose mode routing), old value was 0
08:19:25 warn connmand[474]: ipconfig state 4 ipconfig method 1
08:19:25 info connmand[474]: usb0 {add} route 84.19.146.225 gw 192.168.1.1 scope 0 <UNIVERSE>
08:19:25 info connmand[474]: vpn0 {del} route fe80:: gw :: scope 0 <UNIVERSE>
08:19:25 info connmand[474]: vpn0 {del} route ff00:: gw :: scope 0 <UNIVERSE>
08:19:25 info connmand[474]: vpn0 {add} route 10.128.0.0 gw 10.129.0.1 scope 0 <UNIVERSE>
08:19:25 info connmand[474]: vpn0 {add} route 10.127.0.0 gw 10.129.0.1 scope 0 <UNIVERSE>
08:19:25 info connmand[474]: vpn0 {add} route 10.129.0.0 gw 10.129.0.1 scope 0 <UNIVERSE>


Time passes by (~12hrs) and unfortunately we get kicked out from the network:


20:17:52 debug ofonod[532]: ../git/src/network.c:ofono_netreg_status_notify() /ublox_0 status 0 tech -1 lac -1 ci -1
20:17:52 debug ofonod[532]: ../git/src/network.c:current_operator_callback() 0x22b2ed8, 0x22b8888
20:17:52 debug ofonod[532]: ../git/src/gprs.c:netreg_status_changed() 0 (unregistered)
20:17:52 debug ofonod[532]: ../git/src/gprs.c:gprs_netreg_update() attach: 0, driver_attached: 1
20:17:52 debug ofonod[532]: ../git/src/gprs.c:netreg_status_changed() 0 (unregistered)
20:17:52 debug ofonod[532]: ../git/src/gprs.c:gprs_netreg_update() attach: 0, driver_attached: 0
20:17:52 debug ofonod[532]: ../git/src/gprs.c:ofono_gprs_status_notify() /ublox_0 status unknown (4)
20:17:52 debug ofonod[532]: ../git/src/gprs.c:gprs_attach_callback() /ublox_0 error = 0
20:17:52 debug ofonod[532]: ../git/src/network.c:ofono_netreg_status_notify() /ublox_0 status 3 tech -1 lac -1 ci -1
20:17:52 debug ofonod[532]: ../git/src/network.c:current_operator_callback() 0x22b2ed8, (nil)
20:17:52 debug ofonod[532]: ../git/src/gprs.c:netreg_status_changed() 3 (denied)
20:17:52 debug ofonod[532]: ../git/src/gprs.c:gprs_netreg_update() attach: 0, driver_attached: 0
20:17:52 debug ofonod[532]: ../git/src/gprs.c:registration_status_cb() /ublox_0 error 0 status 3
20:17:52 debug ofonod[532]: ../git/src/gprs.c:ofono_gprs_status_notify() /ublox_0 status denied (3)
20:17:52 debug ofonod[532]: ../git/src/gprs.c:ofono_gprs_detached_notify() /ublox_0
20:17:52 debug ofonod[532]: ../git/src/gprs.c:gprs_attached_update() 0x22aec78, attached: 0, gprs->attached: 1
20:17:52 debug ofonod[532]: ../git/src/gprs.c:gprs_set_attached_property() 0x22aec78 1 -> 0
20:17:52 info connmand[474]: rp_filter restored to 0
20:17:52 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:52 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:52 info connman-vpnd[481]: pid 622 was not killed, retrying after 2 sec
20:17:52 err connmand[474]: notifier disconnect underflow
20:17:52 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:52 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:52 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:52 info connman-vpnd[481]: vpn0 {update} flags 37009 <UP>
20:17:52 info connman-vpnd[481]: vpn0 {newlink} index 8 operstate 2 <DOWN>
20:17:52 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:52 debug ofonod[532]: ../git/plugins/udevng.c:remove_device() /sys/devices/virtual/net/vpn0
20:17:52 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:52 info connmand[474]: usb0 {del} address 192.168.1.100/24 label usb0
20:17:52 info connmand[474]: usb0 {del} route 192.168.1.0 gw 0.0.0.0 scope 253 <LINK>
20:17:52 info connmand[474]: (null) {RX} 0 packets 0 bytes
20:17:52 info connmand[474]: (null) {TX} 3 packets 128 bytes
20:17:52 info connmand[474]: (null) {update} flags 37009 <UP>
20:17:52 info connmand[474]: vpn0 {newlink} index 8 address 00:00:00:00:00:00 mtu 1500
20:17:52 info connmand[474]: vpn0 {newlink} index 8 operstate 2 <DOWN>
20:17:52 info connmand[474]: (null) {RX} 0 packets 0 bytes
20:17:52 info connmand[474]: (null) {TX} 3 packets 128 bytes
20:17:52 info connmand[474]: (null) {update} flags 102609 <UP,RUNNING,LOWER_UP>
20:17:52 info connmand[474]: vpn0 {newlink} index 8 address 00:00:00:00:00:00 mtu 1500
20:17:52 info connmand[474]: vpn0 {newlink} index 8 operstate 6 <UP>
20:17:52 info connmand[474]: (null) {RX} 0 packets 0 bytes
20:17:52 info connmand[474]: (null) {TX} 3 packets 128 bytes
20:17:52 info connmand[474]: (null) {update} flags 37008 <DOWN>
20:17:52 info connmand[474]: vpn0 {newlink} index 8 address 00:00:00:00:00:00 mtu 1500
20:17:52 info connmand[474]: vpn0 {newlink} index 8 operstate 2 <DOWN>
20:17:52 info connmand[474]: (null) {del} address 10.129.36.7/16 label vpn0
20:17:52 info connmand[474]: vpn0 {dellink} index 8 operstate 2 <DOWN>
20:17:52 info connmand[474]: (null) {RX} 0 packets 0 bytes
20:17:52 info connmand[474]: (null) {TX} 3 packets 128 bytes
20:17:52 info connmand[474]: (null) {remove} index 8
20:17:52 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:52 info connman-vpnd[481]: vpn0 {update} flags 102609 <UP,RUNNING,LOWER_UP>
20:17:52 info connman-vpnd[481]: vpn0 {newlink} index 8 operstate 6 <UP>
20:17:52 info connman-vpnd[481]: vpn0 {update} flags 37008 <DOWN>
20:17:52 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:52 info connman-vpnd[481]: vpn0 {newlink} index 8 operstate 2 <DOWN>
20:17:52 info connman-vpnd[481]: vpn0 {dellink} index 8 operstate 2 <DOWN>
20:17:52 info connman-vpnd[481]: vpn0 {remove} index 8
20:17:55 debug ofonod[532]: ../git/src/network.c:ofono_netreg_status_notify() /ublox_0 status 3 tech -1 lac -1 ci -1
20:17:55 debug ofonod[532]: ../git/src/network.c:current_operator_callback() 0x22b2ed8, (nil)
20:17:55 debug ofonod[532]: ../git/src/gprs.c:netreg_status_changed() 3 (denied)
20:17:55 debug ofonod[532]: ../git/src/gprs.c:gprs_netreg_update() attach: 0, driver_attached: 0


We get registered again:


20:17:57 debug ofonod[532]: ../git/drivers/ubloxmodem/network-registration.c:ctze_notify() tz +04 dst 0 time 20/03/14,21:18:19
20:17:57 debug ofonod[532]: ../git/src/network.c:ofono_netreg_time_notify() net time 2020-03-14 21:18:19 utcoff 3600 dst 0
20:17:57 debug ofonod[532]: ../git/src/network.c:ofono_netreg_status_notify() /ublox_0 status 5 tech 2 lac 57005 ci 2147483647
20:17:57 debug ofonod[532]: ../git/src/gprs.c:netreg_status_changed() 5 (roaming)
20:17:57 debug ofonod[532]: ../git/src/gprs.c:gprs_netreg_update() attach: 1, driver_attached: 0
20:17:57 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:cops_numeric_cb() Cops numeric got mcc: XXX, mnc: XX
20:17:57 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:csq_cb() csq_cb: 27
20:17:57 debug ofonod[532]: ../git/src/network.c:ofono_netreg_strength_notify() strength 87
20:17:57 debug ofonod[532]: ../git/src/gprs.c:gprs_attach_callback() /ublox_0 error = 0
20:17:57 debug ofonod[532]: ../git/src/gprs.c:ofono_gprs_status_notify() /ublox_0 status roaming (5)
20:17:57 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:cops_cb() cops_cb: Oper, XXX XX 2
20:17:57 debug ofonod[532]: ../git/src/network.c:current_operator_callback() 0x22b2ed8, (nil)
20:17:57 debug ofonod[532]: ../git/src/gprs.c:netreg_status_changed() 5 (roaming)
20:17:57 debug ofonod[532]: ../git/src/gprs.c:gprs_netreg_update() attach: 1, driver_attached: 1
20:17:57 debug ofonod[532]: ../git/src/gprs.c:registration_status_cb() /ublox_0 error 0 status 5
20:17:57 debug ofonod[532]: ../git/src/gprs.c:ofono_gprs_status_notify() /ublox_0 status roaming (5)
20:17:57 debug ofonod[532]: ../git/src/gprs.c:gprs_attached_update() 0x22aec78, attached: 1, gprs->attached: 0
20:17:57 debug ofonod[532]: ../git/src/gprs.c:gprs_set_attached_property() 0x22aec78 0 -> 1
20:17:58 debug ofonod[532]: ../git/src/network.c:ofono_netreg_status_notify() /ublox_0 status 5 tech 2 lac 20201 ci 8577130
20:17:58 debug ofonod[532]: ../git/src/gprs.c:netreg_status_changed() 5 (roaming)


Data bearer attached again: Seems like a try is done to connect to the vpn.


20:17:58 debug ofonod[532]: ../git/src/gprs.c:gprs_netreg_update() attach: 1, driver_attached: 1
20:17:58 warn connmand[474]: ipconfig state 3 ipconfig method 1
20:17:58 info connmand[474]: Setting hostname to <hostname>
20:17:58 info connmand[474]: usb0 {add} address 192.168.1.100/24 label usb0 family 2
20:17:58 info connmand[474]: usb0 {add} route 192.168.1.0 gw 0.0.0.0 scope 253 <LINK>
20:17:58 info connmand[474]: usb0 {add} route 192.168.1.1 gw 0.0.0.0 scope 253 <LINK>
20:17:58 info connmand[474]: usb0 {add} route 0.0.0.0 gw 192.168.1.1 scope 0 <UNIVERSE>
20:17:58 warn connmand[474]: ipconfig state 2 ipconfig method 1
20:17:58 info connmand[474]: vpn0 {create} index 9 type 65534 <NONE>
20:17:58 info connmand[474]: vpn0 {update} flags 4240 <DOWN>
20:17:58 info connmand[474]: vpn0 {newlink} index 9 address 00:00:00:00:00:00 mtu 1500
20:17:58 info connmand[474]: vpn0 {newlink} index 9 operstate 2 <DOWN>
20:17:58 info connman-vpnd[481]: vpn0 {create} index 9 type 65534 <NONE>
20:17:58 info connman-vpnd[481]: vpn0 {update} flags 4240 <DOWN>
20:17:58 info connman-vpnd[481]: vpn0 {newlink} index 9 operstate 2 <DOWN>
20:17:58 warn connmand[474]: ipconfig state 2 ipconfig method 1
20:17:58 debug ofonod[532]: ../git/plugins/udevng.c:add_serial_device() Device is missing required OFONO_DRIVER property
20:17:58 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:cops_numeric_cb() Cops numeric got mcc: XXX, mnc: XX
20:17:58 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:csq_cb() csq_cb: 27
20:17:58 warn connman-vpnd[481]: Connected management socket
20:17:58 warn connman-vpnd[481]: openvpn request >INFO:OpenVPN Management Interface Version 1 -- type 'help' for more info^M
20:17:58 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:cops_cb() cops_cb: OPER, XXX XX 2
20:17:58 debug ofonod[532]: ../git/src/network.c:current_operator_callback() 0x22b2ed8, 0x22b8888
20:17:59 debug ofonod[532]: ../git/plugins/udevng.c:check_modem_list()
20:17:59 debug ofonod[532]: ../git/drivers/ubloxmodem/gprs-context.c:cgev_notify() cid 1, active cid: 1


Suddenly the context gets deactivated, during the time vpn tries to connect


20:17:59 debug ofonod[532]: ../git/src/gprs.c:ofono_gprs_context_deactivated() 0x22aeb38 0x22aec78 1
20:17:59 info connman-vpnd[481]: usb0 {update} flags 4098 <DOWN>
20:17:59 info connmand[474]: usb0 {RX} 7696 packets 1329655 bytes
20:17:59 info connman-vpnd[481]: usb0 {newlink} index 7 address 02:07:01:18:00:0B mtu 1400
20:17:59 info connmand[474]: usb0 {TX} 8199 packets 1553446 bytes
20:17:59 info connman-vpnd[481]: usb0 {newlink} index 7 operstate 2 <DOWN>
20:17:59 info connmand[474]: usb0 {update} flags 4098 <DOWN>
20:17:59 info connmand[474]: usb0 {newlink} index 7 address 02:07:01:18:00:0B mtu 1400
20:17:59 info connmand[474]: usb0 {newlink} index 7 operstate 2 <DOWN>
20:17:59 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:59 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:59 info connman-vpnd[481]: pid 3204 was not killed, retrying after 2 sec
20:17:59 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:59 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:59 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:59 info connmand[474]: usb0 {del} address 192.168.1.100/24 label usb0
20:17:59 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:59 warn connmand[474]: ipconfig state 2 ipconfig method 1
20:17:59 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:59 debug ofonod[532]: ../git/drivers/ubloxmodem/gprs-context.c:ublox_gprs_activate_primary() cid 1
20:17:59 info connmand[474]: vpn0 {dellink} index 9 operstate 2 <DOWN>
20:17:59 info connmand[474]: (null) {remove} index 9
20:17:59 debug ofonod[532]: ../git/plugins/udevng.c:remove_device() /sys/devices/virtual/net/vpn0
20:17:59 info connman-vpnd[481]: vpn0 {dellink} index 9 operstate 2 <DOWN>
20:17:59 info connman-vpnd[481]: vpn0 {remove} index 9
20:17:59 warn connmand[474]: ipconfig state 6 ipconfig method 1
20:17:59 debug ofonod[532]: ../git/drivers/ubloxmodem/gprs-context.c:cgdcont_cb() ok 1
20:17:59 warn connmand[474]: ipconfig state 7 ipconfig method 1
20:18:00 debug ofonod[532]: ../git/drivers/ubloxmodem/gprs-context.c:cgact_enable_cb() ok 1
20:18:00 debug ofonod[532]: ../git/src/modem.c:get_modem_property() modem 0x22aec00 property NetworkInterface
20:18:00 debug ofonod[532]: ../git/src/gprs.c:pri_activate_callback() 0x22b9b68


Context is activated again. Connman manage to get time via ntp and things looks good, except that the vpn is not reconnected.


20:18:00 info connman-vpnd[481]: usb0 {update} flags 69699 <UP,RUNNING,LOWER_UP>
20:18:00 info connman-vpnd[481]: usb0 {newlink} index 7 address 02:07:01:18:00:0B mtu 1400
20:18:00 info connman-vpnd[481]: usb0 {newlink} index 7 operstate 0 <UNKNOWN>
20:18:00 info connmand[474]: usb0 {RX} 7696 packets 1329655 bytes
20:18:00 info connmand[474]: usb0 {TX} 8199 packets 1553446 bytes
20:18:00 info connmand[474]: usb0 {update} flags 69699 <UP,RUNNING,LOWER_UP>
20:18:00 info connmand[474]: usb0 {newlink} index 7 address 02:07:01:18:00:0B mtu 1400
20:18:00 info connmand[474]: usb0 {newlink} index 7 operstate 0 <UNKNOWN>
20:18:00 warn connmand[474]: ipconfig state 3 ipconfig method 1
20:18:00 info connmand[474]: Setting hostname to <hostname>
20:18:00 debug ofonod[532]: ../git/src/network.c:ofono_netreg_status_notify() /ublox_0 status 5 tech 2 lac 57005 ci 2147483647
20:18:00 debug ofonod[532]: ../git/src/gprs.c:netreg_status_changed() 5 (roaming)
20:18:00 debug ofonod[532]: ../git/src/gprs.c:gprs_netreg_update() attach: 1, driver_attached: 1
20:18:00 debug ofonod[532]: ../git/drivers/atmodem/gprs.c:at_cgdcont_read_cb() ok 1
20:18:00 debug ofonod[532]: ../git/src/gprs.c:ofono_gprs_cid_activated() cid 1
20:18:00 debug ofonod[532]: ../git/src/gprs.c:ofono_gprs_cid_activated() cid 1 already activated
20:18:00 info connmand[474]: usb0 {add} address 192.168.1.100/24 label usb0 family 2
20:18:00 info connmand[474]: usb0 {add} route 192.168.1.0 gw 0.0.0.0 scope 253 <LINK>
20:18:00 info connmand[474]: usb0 {add} route 192.168.1.1 gw 0.0.0.0 scope 253 <LINK>
20:18:00 info connmand[474]: usb0 {add} route 0.0.0.0 gw 192.168.1.1 scope 0 <UNIVERSE>
20:18:00 info connmand[474]: usb0 {add} route 212.227.81.55 gw 192.168.1.1 scope 0 <UNIVERSE>
20:18:00 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:cops_numeric_cb() Cops numeric got mcc: XXX, mnc: XX
20:18:01 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:csq_cb() csq_cb: 29
20:18:01 debug ofonod[532]: ../git/src/network.c:ofono_netreg_strength_notify() strength 93
20:18:01 info connmand[474]: ntp: adjust (jump): +22.500568 sec
20:18:23 info connmand[474]: usb0 {del} route 212.227.81.55 gw 192.168.1.1 scope 0 <UNIVERSE>
20:18:23 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:cops_cb() cops_cb: Oper, XXX XX 2
20:18:23 debug ofonod[532]: ../git/src/network.c:current_operator_callback() 0x22b2ed8, 0x22b8888
20:18:26 debug ofonod[532]: ../git/src/network.c:ofono_netreg_status_notify() /ublox_0 status 5 tech 2 lac 57005 ci 2147483647
20:18:26 debug ofonod[532]: ../git/src/gprs.c:netreg_status_changed() 5 (roaming)
20:18:26 debug ofonod[532]: ../git/src/gprs.c:gprs_netreg_update() attach: 1, driver_attached: 1
20:18:26 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:cops_numeric_cb() Cops numeric got mcc: XXX, mnc: XX
20:18:26 debug ofonod[532]: ../git/drivers/atmodem/network-registration.c:csq_cb() csq_cb: 29





Den tors 23 jan. 2020 kl 15:38 skrev Jussi Laakkonen <jussi.laakkonen@jolla.com>:
Hi Richard,

On 1/22/20 1:50 PM, Richard Röjfors wrote:
>
> Yes we are using TCP.
>

I assumed so, I think I faced a similar problem with our setup testing
free VPNBook OpenVPN using TCP. But yours may still be a different one.

>
> Sounds great! I will try to verify it. Its not super easy to reproduce,
> but over time and a few
> devices it always happens. I'm thinking I could hack ofono a little to
> simulate
> the situation....
>

I submitted a patch for OpenVPN plugin just moments ago to connman list.
Please check if that improves your situation. After all, it is fixing a
regression introduced by the changes I sent for OpenVPN.

I still have a hunch there could be an improvement in place for the
vpn-provider.c to track the connman state, and to delay the connection
if connman is not reporting to be online. This would prevent connections
to VPNs when, in case just like yours, the default service (mobile data,
wifi) goes down only momentarily.

In our fork we have this functionality already implemented. Now I just
need to find time to create a patch/patches against connman upstream for
Daniel and others reading the list to review.

Sincerely,
  Jussi