endless spinlock

[jackfreed]

Hi,

i have a problem where from time to time the spinlock seems to be endless.
i managed to reproduce it when resetting the connection around the time where login happens using

iptables -A OUTPUT -o eth0 -d 149.154.167.50/32 -p tcp -j REJECT --reject-with tcp-reset

the log looks like this:

2020/04/16 19:10:58 [0-1691844592411390537] read: type: mtproto.TL_rpc_result, data: {6816358161102222444 Pts:1212 Date:1587057058 Seq:315 UnreadCount:1 }, err: <nil>
2020/04/16 19:10:58 [0-1691844592411390537] updatesState: {"Pts":1212,"Date":1587057058,"Seq":315,"UnreadCount":1}
2020/04/16 19:10:58 [0-1691844592411390537] read: type: <nil>, data: <nil>, err: read tcp 10.0.0.2:52164->149.154.167.50:443: read: connection reset by peer
2020/04/16 19:10:58 [0-1691844592411390537] read: lost connection (read tcp 10.0.0.2:52164->149.154.167.50:443: read: connection reset by peer). reconnect to 149.154.167.50:443
2020/04/16 19:10:58 [0-1691844592411390537] send mtproto.TL_msgs_ack: {}
2020/04/16 19:10:58 [0-1691844592411390537] notify Event, mtproto.SessionEstablished: {}, to [0xc0009baa80]
2020/04/16 19:10:58 [0-1691844592411390537] ping: start
2020/04/16 19:10:58 [mconn 1156161785] bind session 1691844592411390537
2020/04/16 19:10:58 [mconn 1156161785] start
2020/04/16 19:10:58 [0-1691844592411390537] notify Event, mtproto.refreshSession: {}, to [0xc0009baa80]
2020/04/16 19:10:58 [mconn 1156161785] session event mtproto.ConnectionOpened({0xc00000c1e0 0})
2020/04/16 19:10:58 [mconn 1156161785] pass the session to bindSession ch
2020/04/16 19:10:58 [mconn 1156161785] opened
2020/04/16 19:10:58 [mconn 1156161785] with session, 0
2020/04/16 19:10:58 [MM 1023332122] session established 1691844592411390537
2020/04/16 19:10:58 [MM 1023332122] connectionOpened  1156161785
2020/04/16 19:10:58 [MM 1023332122] refreshSession  1691844592411390537
2020/04/16 19:10:58 [mconn 1156161785] sesssin passed
2020/04/16 19:10:58 [mconn 1156161785] bind: mconn.discardedUpdatesState is nil
2020/04/16 19:10:58 [mconn 1156161785] session request 0xc0000a49c0
2020/04/16 19:10:58 [1156161785-1691844592411390537] notify Event, mtproto.discardSession: {}, to [0xc0009baa80 0xc0009bb6e0]
2020/04/16 19:10:58 [mconn 1156161785] session event mtproto.discardSession({1156161785 1691844592411390537 0xc0001a09c0})
2020/04/16 19:10:58 [mconn 1156161785] session(1691844592411390537) will be discarded
2020/04/16 19:10:58 [MM 1023332122] sessionBound: session 1691844592411390537 is bound to mconn 1156161785
2020/04/16 19:10:58 [mconn 1156161785] session event mtproto.sessionUnbound({0xc00000c1e0 1691844592411390537})
2020/04/16 19:10:58 [mconn 1156161785] unbound to session 1691844592411390537
2020/04/16 19:10:58 [mconn 1156161785] session event mtproto.sessionBound({0xc00000c1e0 1691844592411390537})
2020/04/16 19:10:58 [mconn 1156161785] bound to session 1691844592411390537
2020/04/16 19:10:58 [MM 1023332122] discard session  1691844592411390537
2020/04/16 19:10:58 [MM 1023332122] sessionUnbound: session 1691844592411390537 is unbound from mconn 1156161785
2020/04/16 19:10:58 [1156161785-1691844592411390537] send err: write tcp 10.0.0.2:52164->149.154.167.50:443: write: broken pipe
2020/04/16 19:10:58 [1156161785-1691844592411390537] send *mtproto.ReqUsersGetFullUser: {"Id":{"Value":{"InputUserSelf":{}}}}
2020/04/16 19:10:59 [1156161785-1691844592411390537] send err: write tcp 10.0.0.2:52164->149.154.167.50:443: write: broken pipe
2020/04/16 19:10:59 [1156161785-1691844592411390537] send: stop
2020/04/16 19:10:59 [1156161785-1691844592411390537] read: wait for inner routine ...
2020/04/16 19:10:59 [1156161785-1691844592411390537] read: stop
2020/04/16 19:10:59 [1156161785-1691844592411390537] notify Event, mtproto.SessionDiscarded: {}, to [0xc0009baa80 0xc0009bb6e0]
2020/04/16 19:10:59 [MM 1023332122] session is discarded. keep its updates state, (json): {"Pts":1212,"Date":1587057058,"Seq":315}
2020/04/16 19:10:59 [MM 1023332122] req loadsession
2020/04/16 19:10:59 [MM 1023332122] session discarded  1691844592411390537
2020/04/16 19:10:59 [MM 1023332122] loadsession of conn  1156161785
2020/04/16 19:10:59 [0-4373503034935838490] dial TCP to 149.154.167.50:443
2020/04/16 19:10:59 [mconn 1156161785] session event mtproto.SessionDiscarded({1156161785 1691844592411390537 0xc000c0f240})
2020/04/16 19:10:59 [MM 1023332122] connect failure: Handshaking Failure: dial tcp 0.0.0.0:0->149.154.167.50:443: connect: connection refused
2020/04/16 19:10:59 [0-4373503034935838490] notify Event, mtproto.SessionDiscarded: {}, to [0xc0009baa80]
2020/04/16 19:10:59 [MM 1023332122] session discarded  4373503034935838490
2020/04/16 19:10:59 [MM 1023332122] refreshSession failure; loadSession failure; Handshaking Failure: dial tcp 0.0.0.0:0->149.154.167.50:443: connect: connection refused; connID: 0, session: &{0 4373503034935838490 [] 0xc0004349d0 <nil> 0xc000450de0 <nil> <nil> <nil> <nil> false false false {{} [0 0 0]} {{} [0 0 0]} {{} [0 0 0]} 0xc000312630 <nil> 0 map[] map[] 0 0 {... ... ... ... 60000000000 500000000 {"phone":.....,"api_id":......,"api_hash":"........","ip":"149.154.167.50","port":443,"salt":"...........","auth_key":"..........."} 0xecb780} <nil> <nil> map[] 0.0.0.0}
2020/04/16 19:10:59 [MM 1023332122] retry refreshSession
2020/04/16 19:10:59 [MM 1023332122] refreshSession is done.
2020/04/16 19:10:59 [MM 1023332122] refreshSession  4373503034935838490

then the following never ends:

2020/04/16 19:11:00 [MM 1023332122] spinlocked. Session(4373503034935838490) is waiting for a response from either invokeWithLayer or updatesGetState.
2020/04/16 19:11:01 [MM 1023332122] spinlocked. Session(4373503034935838490) is waiting for a response from either invokeWithLayer or updatesGetState.
2020/04/16 19:11:02 [MM 1023332122] spinlocked. Session(4373503034935838490) is waiting for a response from either invokeWithLayer or updatesGetState.
2020/04/16 19:11:03 [MM 1023332122] spinlocked. Session(4373503034935838490) is waiting for a response from either invokeWithLayer or updatesGetState.
2020/04/16 19:11:04 [MM 1023332122] spinlocked. Session(4373503034935838490) is waiting for a response from either invokeWithLayer or updatesGetState.
2020/04/16 19:11:05 [MM 1023332122] spinlocked. Session(4373503034935838490) is waiting for a response from either invokeWithLayer or updatesGetState.
2020/04/16 19:11:06 [MM 1023332122] spinlocked. Session(4373503034935838490) is waiting for a response from either invokeWithLayer or updatesGetState.
2020/04/16 19:11:07 [MM 1023332122] spinlocked. Session(4373503034935838490) is waiting for a response from either invokeWithLayer or updatesGetState.
2020/04/16 19:11:08 [MM 1023332122] spinlocked. Session(4373503034935838490) is waiting for a response from either invokeWithLayer or updatesGetState.
2020/04/16 19:11:09 [MM 1023332122] spinlocked. Session(4373503034935838490) is waiting for a response from either invokeWithLayer or updatesGetState.
2020/04/16 19:11:10 [MM 1023332122] spinlocked. Session(4373503034935838490) is waiting for a response from either invokeWithLayer or updatesGetState.

i already increased any timeouts to 30s for testing, but that did not help.

any ideas?

thanks in advance.