iOS 10: No logon possible immediately after app start


#1

I’ve successfully migrated my app to iOS 10 and solved many of the miracles involved (writing a guide chapter on this is still on my to-do list). But there’s one, quite annoying problem that still persists: If a user opens my app for the very first time (i.e. right after the download from the app-store) and immediately tries to logon, the logon attempt fails silently, i.e. the login screen is still visible, without any further reaction from the app.

Everything else is working fine before the logon attempt, i.e. subscribed data is displayed, and other web-sockets based communications (like suggest search based on Arunoda’s packages) works. So the problem should not be related to the general web-sockets communications problem on iOS 10, which I could solve by setting the required meta flag.

However, as soon as the logon attempt is being made, all other subsequent communication is failing, too. That means: subscriptions are not being executed anymore, and no result data is being displayed. I can still browse through the app, but I don’t get any data. Neither the Xcode log nor the Safari log show any errors. So I don’t have a clue what is happening here :-/

Interestingly, the problem seems to disappear when you close the app completely and re-open it afterwards. From then on, the app seems to work as expected. So the problem might be related to the hot-code-push mechanism. I also noticed that the problem does not appear, if I browser some pages in the app before trying to logon.

Any ideas what might cause this strange behaviour? Any help is appreciated.

BTW: I’m still on Meteor 1.2 and using useraccounts-bootstrap for authentication.


Meteor 1.2 app cannot connect to server on iOS 10
#2

I have a mobile app that works fine on iOS 10. The way my setup is different from yours is:

  • I’m on Meteor 1.4
  • I disabled hot code push for the app

Try to update your app to 1.4 (even if you don’t plan to use ES6 modules yet) and see if that helps. If not, try to disable hot code push.


#3

@M4v3R: Thanks for answering. Well, upgrading to 1.4 is not an option for me, since it comes with a newer Cordova version which is not compatible to some of my 3rd-party Cordova plugins (they haven’t been updated yet).

What exactly do you mean by “disabling HCP”? At least in Meteor 1.2, HCP cannot be disabled completely. You can prevent it from restarting the app directly, but the download is still performed in the background and applied once the app restarts. This is how I am doing it now. I’m also not really sure if HCP is really responsible for my problem.


#4

Yeah, what I meant by disabling HCP was disabling the refreshing while app is running, which for me caused more harm than good.

Unfortunately every major iOS version comes with some backwards-incompatible stuff and if you don’t update your Cordova you inevitably will run into problems.


#5

Well, according to what I’ve read in the issues, the most recent Cordova version is even not fully compatible with iOS 10. But I doubt this problem has something to do with Cordova itself. I digged a bit deeper into it now, and in the Safari debugger I cannot see any network traffic occurring once I try to log-on (and after that). Since everything else works perfectly until I try to log-in, the problem has to be related to the login-process itself somehow.

Once the problem occurs, any follow-up method call leads to an error in Safari’s console:

Received error from server:  Must connect first

followed by the method signature. It seems as if the connection to the server is completely lost at this point.

On iOS 9.3, the app works just fine.

Strange thing is, it sometimes works if I close the app and restart it. But sometimes it doesn’t. Sometimes, it is also enough to browse around in the app before trying to login. It’s really weird.


#6

There’s also a lot of errors logged in the Xcode window before the problem occurs, which only appear on iOS 10. But they appear when the app is still responding, i.e. before I try to log-in. Here is a sample:

2016-09-28 21:35:11.534334 guzz[5209:292814] subsystem: com.apple.network, category: , enable_level: 0, persist_level: 0, default_ttl: 0, info_ttl: 0, debug_ttl: 0, generate_symptoms: 0, enable_oversize: 0, privacy_setting: 2, enable_private_data: 0
2016-09-28 21:35:11.534583 guzz[5209:292809] [] tcp_connection_create_with_endpoint_and_parameters 2 pancake.apple.com 443
2016-09-28 21:35:11.534882 guzz[5209:292814] [] tcp_connection_create_with_endpoint_and_parameters 1 gsp1.apple.com 80
2016-09-28 21:35:11.535075 guzz[5209:292809] [] tcp_connection_start 2 starting
2016-09-28 21:35:11.535275 guzz[5209:292814] [] tcp_connection_start 1 starting
2016-09-28 21:35:11.535512 guzz[5209:292809] [] nw_connection_create creating connection to pancake.apple.com:443
2016-09-28 21:35:11.535831 guzz[5209:292814] [] nw_connection_create creating connection to gsp1.apple.com:80
2016-09-28 21:35:11.536042 guzz[5209:292809] [] tcp_connection_start starting tc_nwconn=0x7fe9d3e02530
2016-09-28 21:35:11.536219 guzz[5209:292814] [] tcp_connection_start starting tc_nwconn=0x7fe9d3f02370
2016-09-28 21:35:11.536381 guzz[5209:292809] [] __nw_connection_start_block_invoke 1 starting
2016-09-28 21:35:11.536653 guzz[5209:292809] [] nw_endpoint_handler_start [1 pancake.apple.com:443 initial path (null)]
2016-09-28 21:35:11.536854 guzz[5209:292809] [] nw_connection_endpoint_report [1 pancake.apple.com:443 initial path (null)] reported event path:start
2016-09-28 21:35:11.537327 guzz[5209:292809] [] nw_endpoint_handler_path_change [1 pancake.apple.com:443 waiting path (satisfied)]
2016-09-28 21:35:11.537520 guzz[5209:292809] [] nw_connection_endpoint_report [1 pancake.apple.com:443 waiting path (satisfied)] reported event path:satisfied
2016-09-28 21:35:11.537745 guzz[5209:292809] [] nw_connection_endpoint_report [1 pancake.apple.com:443 waiting path (satisfied)] skipping state update
2016-09-28 21:35:11.538031 guzz[5209:292809] [] nw_endpoint_proxy_handler_should_use_proxy Looking up proxy for hostname: pancake.apple.com, ifindex: 0
2016-09-28 21:35:11.538636 guzz[5209:292809] subsystem: com.apple.SystemConfiguration, category: SCPreferences, enable_level: 0, persist_level: 0, default_ttl: 0, info_ttl: 0, debug_ttl: 0, generate_symptoms: 0, enable_oversize: 0, privacy_setting: 2, enable_private_data: 0
2016-09-28 21:35:11.539575 guzz[5209:292809] [] -[NWConcrete_nw_endpoint_resolver startWithHandler:] [1 pancake.apple.com:443 waiting resolver (satisfied)]
2016-09-28 21:35:11.539807 guzz[5209:292809] [] nw_connection_endpoint_report [1 pancake.apple.com:443 in_progress resolver (satisfied)] reported event resolver:start_dns
2016-09-28 21:35:11.540326 guzz[5209:292809] [] nw_resolver_create_dns_service_on_queue Starting host resolution pancake.apple.com:443, flags 0x4000d000
2016-09-28 21:35:11.540518 guzz[5209:292809] [] __nw_connection_start_block_invoke 2 starting
2016-09-28 21:35:11.540739 guzz[5209:292814] [] nw_resolver_host_resolve_callback flags=0x3 ifindex=0 error=NoSuchRecord(-65554) hostname=pancake.apple.com. addr=::.0 ttl=60
2016-09-28 21:35:11.540953 guzz[5209:292809] [] nw_endpoint_handler_start [2 gsp1.apple.com:80 initial path (null)]
2016-09-28 21:35:11.541126 guzz[5209:292809] [] nw_connection_endpoint_report [2 gsp1.apple.com:80 initial path (null)] reported event path:start
2016-09-28 21:35:11.541525 guzz[5209:292809] [] nw_endpoint_handler_path_change [2 gsp1.apple.com:80 waiting path (satisfied)]
2016-09-28 21:35:11.541691 guzz[5209:292809] [] nw_connection_endpoint_report [2 gsp1.apple.com:80 waiting path (satisfied)] reported event path:satisfied
2016-09-28 21:35:11.541870 guzz[5209:292809] [] nw_connection_endpoint_report [2 gsp1.apple.com:80 waiting path (satisfied)] skipping state update
2016-09-28 21:35:11.542067 guzz[5209:292809] [] nw_endpoint_proxy_handler_should_use_proxy Looking up proxy for hostname: gsp1.apple.com, ifindex: 0
2016-09-28 21:35:11.542585 guzz[5209:292809] [] -[NWConcrete_nw_endpoint_resolver startWithHandler:] [2 gsp1.apple.com:80 waiting resolver (satisfied)]
2016-09-28 21:35:11.542766 guzz[5209:292809] [] nw_connection_endpoint_report [2 gsp1.apple.com:80 in_progress resolver (satisfied)] reported event resolver:start_dns
2016-09-28 21:35:11.543080 guzz[5209:292809] [] nw_resolver_create_dns_service_on_queue Starting host resolution gsp1.apple.com:80, flags 0x4000d000
2016-09-28 21:35:11.543366 guzz[5209:292809] [] nw_resolver_host_resolve_callback flags=0x3 ifindex=0 error=NoSuchRecord(-65554) hostname=gsp1.apple.com. addr=::.0 ttl=60
2016-09-28 21:35:11.562587 guzz[5209:292809] [] nw_resolver_host_resolve_callback flags=0x2 ifindex=0 error=NoError(0) hostname=e6428.e9.akamaiedge.net. addr=104.84.218.211:0 ttl=20
2016-09-28 21:35:11.563099 guzz[5209:292814] [] nw_endpoint_resolver_update [1 pancake.apple.com:443 in_progress resolver (satisfied)] resolver is complete
2016-09-28 21:35:11.563368 guzz[5209:292814] [] nw_endpoint_resolver_update [1 pancake.apple.com:443 in_progress resolver (satisfied)] Adding endpoint handler for 104.84.218.211:443
2016-09-28 21:35:11.563646 guzz[5209:292814] [] nw_endpoint_resolver_update [1 pancake.apple.com:443 in_progress resolver (satisfied)] Updated endpoint list is (104.84.218.211:443)
2016-09-28 21:35:11.563872 guzz[5209:292814] [] nw_connection_endpoint_report [1 pancake.apple.com:443 in_progress resolver (satisfied)] reported event resolver:receive_dns
2016-09-28 21:35:11.564144 guzz[5209:292814] [] nw_endpoint_resolver_start_next_child [1 pancake.apple.com:443 in_progress resolver (satisfied)] starting child endpoint 104.84.218.211:443
2016-09-28 21:35:11.564403 guzz[5209:292814] [] nw_host_stats_add_src recv too small, received 24, expected 28
2016-09-28 21:35:11.564633 guzz[5209:292814] [] nw_endpoint_resolver_start_next_child [1 pancake.apple.com:443 in_progress resolver (satisfied)] starting next child endpoint in 250ms
2016-09-28 21:35:11.564860 guzz[5209:292814] [] nw_endpoint_handler_start [1.1 104.84.218.211:443 initial path (null)]
2016-09-28 21:35:11.565054 guzz[5209:292814] [] nw_endpoint_resolver_receive_report [1 pancake.apple.com:443 in_progress resolver (satisfied)] received child report:[1.1 104.84.218.211:443 initial path (null)]
2016-09-28 21:35:11.565233 guzz[5209:292814] [] nw_connection_endpoint_report [1.1 104.84.218.211:443 initial path (null)] reported event path:start
2016-09-28 21:35:11.565585 guzz[5209:292814] [] nw_endpoint_handler_path_change [1.1 104.84.218.211:443 waiting path (satisfied)]
2016-09-28 21:35:11.565785 guzz[5209:292814] [] nw_endpoint_resolver_receive_report [1 pancake.apple.com:443 in_progress resolver (satisfied)] received child report:[1.1 104.84.218.211:443 waiting path (satisfied)]
2016-09-28 21:35:11.565969 guzz[5209:292814] [] nw_connection_endpoint_report [1.1 104.84.218.211:443 waiting path (satisfied)] reported event path:satisfied
2016-09-28 21:35:11.566151 guzz[5209:292814] [] nw_endpoint_proxy_handler_should_use_proxy Looking up proxy for hostname: <nil>, ifindex: 0
2016-09-28 21:35:11.566793 guzz[5209:292814] [] -[NWConcrete_nw_endpoint_flow startWithHandler:] [1.1 104.84.218.211:443 waiting socket-flow (satisfied)]
2016-09-28 21:35:11.566998 guzz[5209:292814] [] nw_endpoint_flow_setup_socket [1.1 104.84.218.211:443 in_progress socket-flow (satisfied)] creating socket
2016-09-28 21:35:11.567168 guzz[5209:292814] [] nw_endpoint_flow_attach_protocols [1.1 104.84.218.211:443 in_progress socket-flow (satisfied)]
2016-09-28 21:35:11.567795 guzz[5209:292814] [] ____nwlog_simulate_crash_inner_block_invoke dlopen CrashReporterSupport failed
2016-09-28 21:35:11.567970 guzz[5209:292814] [] __nwlog_err_simulate_crash simulate crash failed "nw_socket_set_common_sockopts setsockopt SO_NOAPNFALLBK failed: [42] Protocol not available"
2016-09-28 21:35:11.568325 guzz[5209:292814] [] nw_socket_set_common_sockopts setsockopt SO_NOAPNFALLBK failed: [42] Protocol not available, dumping backtrace:
        [x86_64] libnetcore-856.1.8
    0   libsystem_network.dylib             0x00000001124bd80e __nw_create_backtrace_string + 123
    1   libnetwork.dylib                    0x0000000115dff194 nw_socket_add_input_handler + 3002
    2   libnetwork.dylib                    0x0000000115ddcdb8 nw_endpoint_flow_attach_protocols + 3768
    3   libnetwork.dylib                    0x0000000115ddbdd5 nw_endpoint_flow_setup_socket + 563
    4   libnetwork.dylib                    0x0000000115ddab34 -[NWConcrete_nw_endpoint_flow startWithHandler:] + 2612
    5   libnetwork.dylib                    0x0000000115df5d11 nw_endpoint_handler_path_change + 1261
    6   libnetwork.dylib                    0x0000000115df5740 nw_endpoint_handler_start + 570
    7   libnetwork.dylib                    0x0000000115e0d003 nw_endpoint_resolver_start_next_child + 2240
    8   libdispatch.dylib                   0x000000
2016-09-28 21:35:11.568609 guzz[5209:292814] [] nw_endpoint_flow_attach_protocols [1.1 104.84.218.211:443 in_progress socket-flow (satisfied)] Attached flow protocol
2016-09-28 21:35:11.568776 guzz[5209:292814] [] nw_endpoint_resolver_receive_report [1 pancake.apple.com:443 in_progress resolver (satisfied)] received child report:[1.1 104.84.218.211:443 in_progress socket-flow (satisfied)]
2016-09-28 21:35:11.568949 guzz[5209:292814] [] nw_connection_endpoint_report [1.1 104.84.218.211:443 in_progress socket-flow (satisfied)] reported event flow:start_connect
2016-09-28 21:35:11.569549 guzz[5209:292814] [] nw_resolver_host_resolve_callback flags=0x3 ifindex=0 error=NoError(0) hostname=a1507.b.akamai.net. addr=95.101.89.114:0 ttl=19
2016-09-28 21:35:11.569772 guzz[5209:292814] [] nw_resolver_host_resolve_callback flags=0x2 ifindex=0 error=NoError(0) hostname=a1507.b.akamai.net. addr=95.101.89.107:0 ttl=19
2016-09-28 21:35:11.570026 guzz[5209:292814] [] nw_host_stats_add_src recv too small, received 24, expected 28
2016-09-28 21:35:11.570255 guzz[5209:292814] [] nw_host_stats_add_src recv too small, received 24, expected 28
2016-09-28 21:35:11.570441 guzz[5209:292814] [] sa_dst_compare_internal 95.101.89.107:80@0 = 95.101.89.114:80@0
2016-09-28 21:35:11.570810 guzz[5209:292809] [] nw_endpoint_resolver_update [2 gsp1.apple.com:80 in_progress resolver (satisfied)] resolver is complete
2016-09-28 21:35:11.571245 guzz[5209:292809] [] nw_endpoint_resolver_update [2 gsp1.apple.com:80 in_progress resolver (satisfied)] Adding endpoint handler for 95.101.89.114:80
2016-09-28 21:35:11.571439 guzz[5209:292809] [] nw_endpoint_resolver_update [2 gsp1.apple.com:80 in_progress resolver (satisfied)] Adding endpoint handler for 95.101.89.107:80
2016-09-28 21:35:11.571626 guzz[5209:292809] [] nw_endpoint_resolver_update [2 gsp1.apple.com:80 in_progress resolver (satisfied)] Updated endpoint list is (95.101.89.114:80,95.101.89.107:80)
2016-09-28 21:35:11.571821 guzz[5209:292809] [] nw_connection_endpoint_report [2 gsp1.apple.com:80 in_progress resolver (satisfied)] reported event resolver:receive_dns
2016-09-28 21:35:11.572025 guzz[5209:292809] [] nw_endpoint_resolver_start_next_child [2 gsp1.apple.com:80 in_progress resolver (satisfied)] starting child endpoint 95.101.89.114:80
2016-09-28 21:35:11.572228 guzz[5209:292809] [] nw_host_stats_add_src recv too small, received 24, expected 28
2016-09-28 21:35:11.572411 guzz[5209:292809] [] nw_endpoint_resolver_start_next_child [2 gsp1.apple.com:80 in_progress resolver (satisfied)] starting next child endpoint in 250ms
2016-09-28 21:35:11.572611 guzz[5209:292809] [] nw_endpoint_handler_start [2.1 95.101.89.114:80 initial path (null)]
2016-09-28 21:35:11.572831 guzz[5209:292809] [] nw_endpoint_resolver_receive_report [2 gsp1.apple.com:80 in_progress resolver (satisfied)] received child report:[2.1 95.101.89.114:80 initial path (null)]
2016-09-28 21:35:11.573048 guzz[5209:292809] [] nw_connection_endpoint_report [2.1 95.101.89.114:80 initial path (null)] reported event path:start
2016-09-28 21:35:11.573563 guzz[5209:292809] [] nw_endpoint_handler_path_change [2.1 95.101.89.114:80 waiting path (satisfied)]
2016-09-28 21:35:11.573844 guzz[5209:292809] [] nw_endpoint_resolver_receive_report [2 gsp1.apple.com:80 in_progress resolver (satisfied)] received child report:[2.1 95.101.89.114:80 waiting path (satisfied)]
2016-09-28 21:35:11.574088 guzz[5209:292809] [] nw_connection_endpoint_report [2.1 95.101.89.114:80 waiting path (satisfied)] reported event path:satisfied
2016-09-28 21:35:11.574281 guzz[5209:292809] [] nw_endpoint_proxy_handler_should_use_proxy Looking up proxy for hostname: <nil>, ifindex: 0
2016-09-28 21:35:11.574775 guzz[5209:292809] [] -[NWConcrete_nw_endpoint_flow startWithHandler:] [2.1 95.101.89.114:80 waiting socket-flow (satisfied)]
2016-09-28 21:35:11.574951 guzz[5209:292809] [] nw_endpoint_flow_setup_socket [2.1 95.101.89.114:80 in_progress socket-flow (satisfied)] creating socket
2016-09-28 21:35:11.575126 guzz[5209:292809] [] nw_endpoint_flow_attach_protocols [2.1 95.101.89.114:80 in_progress socket-flow (satisfied)]
2016-09-28 21:35:11.575343 guzz[5209:292809] [] __nwlog_err_simulate_crash simulate crash already simulated "nw_socket_set_common_sockopts setsockopt SO_NOAPNFALLBK failed: [42] Protocol not available"
2016-09-28 21:35:11.575624 guzz[5209:292809] [] nw_socket_set_common_sockopts setsockopt SO_NOAPNFALLBK failed: [42] Protocol not available, dumping backtrace:
        [x86_64] libnetcore-856.1.8
    0   libsystem_network.dylib             0x00000001124bd80e __nw_create_backtrace_string + 123
    1   libnetwork.dylib                    0x0000000115dff194 nw_socket_add_input_handler + 3002
    2   libnetwork.dylib                    0x0000000115ddcdb8 nw_endpoint_flow_attach_protocols + 3768
    3   libnetwork.dylib                    0x0000000115ddbdd5 nw_endpoint_flow_setup_socket + 563
    4   libnetwork.dylib                    0x0000000115ddab34 -[NWConcrete_nw_endpoint_flow startWithHandler:] + 2612
    5   libnetwork.dylib                    0x0000000115df5d11 nw_endpoint_handler_path_change + 1261
    6   libnetwork.dylib                    0x0000000115df5740 nw_endpoint_handler_start + 570
    7   libnetwork.dylib                    0x0000000115e0d003 nw_endpoint_resolver_start_next_child + 2240
    8   libdispatch.dylib                   0x000000
2016-09-28 21:35:11.575847 guzz[5209:292809] [] nw_endpoint_flow_attach_protocols [2.1 95.101.89.114:80 in_progress socket-flow (satisfied)] Attached flow protocol
2016-09-28 21:35:11.576058 guzz[5209:292809] [] nw_endpoint_resolver_receive_report [2 gsp1.apple.com:80 in_progress resolver (satisfied)] received child report:[2.1 95.101.89.114:80 in_progress socket-flow (satisfied)]
2016-09-28 21:35:11.576415 guzz[5209:292809] [] nw_connection_endpoint_report [2.1 95.101.89.114:80 in_progress socket-flow (satisfied)] reported event flow:start_connect
2016-09-28 21:35:11.581574 guzz[5209:292809] [] nw_socket_handle_socket_event Event mask: 0x800
2016-09-28 21:35:11.581774 guzz[5209:292809] [] nw_socket_handle_socket_event Socket received CONNECTED event
2016-09-28 21:35:11.581981 guzz[5209:292809] [] nw_socket_setup_notsent_lowat Set TCP_NOTSENT_LOWAT(16384)
2016-09-28 21:35:11.582231 guzz[5209:292809] [] nw_endpoint_flow_protocol_connected [1.1 104.84.218.211:443 in_progress socket-flow (satisfied)] Output protocol connected
2016-09-28 21:35:11.582917 guzz[5209:292809] [] nw_endpoint_flow_connected_path_change [1.1 104.84.218.211:443 ready socket-flow (satisfied)]
2016-09-28 21:35:11.583115 guzz[5209:292809] [] nw_endpoint_flow_connected_path_change [1.1 104.84.218.211:443 ready socket-flow (satisfied)] Connected path is satisfied

I have no clues where these errors come from, they won’t show up on iOS 9.3. But they have something to do with networking, that’s sure. But they happen when the app is still responding.

EDIT: Just found an explanation for these messages here: https://forums.developer.apple.com/thread/49777. Seems as if this is normal Xcode 8 behaviour.


#7

This hints to a websocket issue, which would suggest to me that Cordova is the culprit.

Can you do a simple test? Temporarily remove all the plugins that are not compatible with latest Cordova version and upgrade to Meteor 1.4, then try again. If it still won’t work then you will know that it’s not Cordova’s / Meteor 1.2 fault :slight_smile:


#8

Just found out these error messages are a new “Xcode 8 loggin feature”, as described here: https://forums.developer.apple.com/thread/49777. So they’re not related to my problem.

I can try to upgrade Meteor without the Cordova plugins. But last time I tried an update (1.1 to 1.2), it was just a nightmare due to the many breaking changes I was facing. It even happened that these problems were still there when I reset back my app to 1.1 using source code revisioning (something in the build system got wrong and I had to re-install Meteor completely to work-around this). After this bad experience, I became quite relectant of updating Meteor, and reading about all these changes in 1.3 and 1.4 won’t make me feel better :slight_smile: But yes, maybe I can track the problem down this way. Won’t help me much though, since updating is not really an option for now :confused: The main reason is the Cordova plugin I am using for WebRTC video streaming.


#9

Hi there, not sure if you ve got this message about slowness using ios 10 as described in this post :"<App Name> May Slow Down your iPhone" message on iOS 10.1

Any help would be more than welcome :slight_smile:


#10

This doesn’t seem to be related. I get this message for other apps, but not for my own app (I’m still on Meteor 1.2, though). But still, I am facing the problem mentioned in the original post, i.e. no logon is possible immediately after app start. This is very annoying and leads to losing users. Still have no clue how to prevent this. Any help is appreciated :slight_smile:


#11

Hey waldgeist!

I have exactly the same issue as you describe unless I am not using Meteor.
Did you find any solution?

Thanks,
Quentin


#12

Yes, it turned out Meteor wasn’t responsible for that. I was using a second party library that included a web socket hack to prevent crashes in Cordova when a web socket message was received and caused an immediate Cordova callback. This hack prevented the iOS app from connecting at app start.