search

coddingtonbear / inthe.am

Access your Taskwarrior tasks from any browser anywhere
https://inthe.am/
GNU Affero General Public License v3.0
591 stars 50 forks source link

The specified session has been invalidated for some reason #301

Closed xrs444 closed 5 years ago

xrs444 commented 6 years ago

Hello, I'm seeing the same issue as in:

"The specified session has been invalidated for some reason" #292

I had Taskwarrior installed on Fedora 28, created an account and synced fine yesterday, with web and task sync working fine.

Today I booted and I get the below errors on my machine, but the web interface seems fine still.

I've tried clearing the tasks on my machine, ensuring I'm logged out of all the web sessions, manually resetting the lock via the website, disabling my machine firewall and re-running the init.

I've not made any network changes, although I will go back over my firewall config to double check nothing's changed.

Any ideas?

Thanks,

Thomas

[xrs444@xlt2 ~]$ task sync init Please confirm that you wish to upload all your pending tasks to the Taskserver (yes/no) yes c: 1 Received packet with illegal length: 16528 Syncing with taskwarrior.inthe.am:53589

The specified session has been invalidated for some reason. Sync failed. Could not connect to the Taskserver. [xrs444@xlt2 ~]$ task sync Syncing with taskwarrior.inthe.am:53589

Could not connect to taskwarrior.inthe.am 53589 Sync failed. Could not connect to the Taskserver. [xrs444@xlt2 ~]$ task diagnostic

task 2.5.1 Platform: Linux

Compiler Version: 8.1.1 20180712 (Red Hat 8.1.1-5) Caps: +stdc +stdc_hosted +LP64 +c8 +i32 +l64 +vp64 +time_t64 Compliance: C++11

Build Features Built: Sep 2 2018 17:17:05 CMake: 3.11.2 libuuid: libuuid + uuid_unparse_lower libgnutls: 3.6.3 Build type:

Configuration File: /home/xrs444/.taskrc (found), 870 bytes, mode 100664 Data: /home/xrs444/.task (found), dir, mode 40775 Locking: Enabled GC: Enabled Server: taskwarrior.inthe.am:53589 CA: ~/.task/intheam.ca.cert.cer, readable, 2405 bytes Trust: ignore hostname Certificate: ~/.task/intheam.cert.cer, readable, 2462 bytes Key: ~/.task/intheam.key.cer, readable, 3664 bytes Ciphers: NORMAL Creds: inthe_am/xrs444/****

Hooks System: Enabled Location: /home/xrs444/.task/hooks (-none-)

Tests $TERM: xterm-256color (255x130) Dups: Scanned 0 tasks for duplicate UUIDs: No duplicates found Broken ref: Scanned 0 tasks for broken references: No broken references found

coddingtonbear commented 6 years ago

I'm afraid this sort of thing almost always means that there's some kind of firewall between your client and Inthe.AM that is preventing the connection from being established.

kellya commented 5 years ago

I am having this same issue when I attempted to set up task syncing on a new host. But I don't think firewall is the issue: I verified that name resolution is getting me to the correct place

dig +short taskwarrior.inthe.am
inthe.am. 74.207.247.134

Testing a connection to the port via telnet succeeds:

telnet taskwarrior.inthe.am 53589 Trying 74.207.247.134... Connected to taskwarrior.inthe.am. Escape character is '^]'.

Yet attempting a sync fails:

task sync c: 1 Received packet with illegal length: 16544 Syncing with taskwarrior.inthe.am:53589

The specified session has been invalidated for some reason. Sync failed. Could not connect to the Taskserver.

Additionally, I tried to setup a sync with freecinc, and that successfully synced. Which at least shows the access to a taskserver running on the internet on port 53589 works.

kellya commented 5 years ago

I found a workaround, but I haven't figured out exactly what is wrong. To make it work, I rsynced .task* from my working machine to the one that was giving the error and everything started working. It appears that there is something in the directory that ends up making it work, but I haven't pinpointed 'what it is. I tried to start with an empty .task, and simply touch ing the files until they all existed, but that didn't make it work. It is dependant on the actual content of the files, but to me makes no sense why any of that would result in an error that looks like it cannot connect to the taskserver ¯\(ツ)/¯

coddingtonbear commented 5 years ago

That is interesting; you may want to check-in with the folks in #taskwarrior on freenode to see if they have any ideas. Inthe.AM uses an (only very slightly) modified fork of the normal taskwarrior taskserver v1.1.0, so if this is a problem with the taskserver, it's likely to be something others have encountered.

adrienthebo commented 5 years ago

I'm running into this issue as well, and I don't think it's a firewall issue. The below log shows that an SSL session is being negotiated which rules out firewall/network issues:

╰─ task rc.debug=1 rc.debug.tls=4 sync
c: INFO Server certificate will be verified but hostname ignored.
c: 3 ASSERT: ../../../lib/x509/x509_ext.c[gnutls_subject_alt_names_get]:110
c: 3 ASSERT: ../../../lib/x509/x509.c[get_alt_name]:1812
c: 3 ASSERT: ../../../lib/nettle/mpi.c[wrap_nettle_mpi_print]:60
c: 2 added 6 protocols, 29 ciphersuites, 18 sig algos and 9 groups into priority list
c: 4 HSK[0x55a3d4b4ce20]: Adv. version: 3.3
c: 2 Keeping ciphersuite 13.02 (GNUTLS_AES_256_GCM_SHA384)
c: 2 Keeping ciphersuite 13.03 (GNUTLS_CHACHA20_POLY1305_SHA256)
c: 2 Keeping ciphersuite 13.01 (GNUTLS_AES_128_GCM_SHA256)
c: 2 Keeping ciphersuite 13.04 (GNUTLS_AES_128_CCM_SHA256)
c: 2 Keeping ciphersuite c0.2c (GNUTLS_ECDHE_ECDSA_AES_256_GCM_SHA384)
c: 2 Keeping ciphersuite cc.a9 (GNUTLS_ECDHE_ECDSA_CHACHA20_POLY1305)
c: 2 Keeping ciphersuite c0.ad (GNUTLS_ECDHE_ECDSA_AES_256_CCM)
c: 2 Keeping ciphersuite c0.0a (GNUTLS_ECDHE_ECDSA_AES_256_CBC_SHA1)
c: 2 Keeping ciphersuite c0.2b (GNUTLS_ECDHE_ECDSA_AES_128_GCM_SHA256)
c: 2 Keeping ciphersuite c0.ac (GNUTLS_ECDHE_ECDSA_AES_128_CCM)
c: 2 Keeping ciphersuite c0.09 (GNUTLS_ECDHE_ECDSA_AES_128_CBC_SHA1)
c: 2 Keeping ciphersuite c0.30 (GNUTLS_ECDHE_RSA_AES_256_GCM_SHA384)
c: 2 Keeping ciphersuite cc.a8 (GNUTLS_ECDHE_RSA_CHACHA20_POLY1305)
c: 2 Keeping ciphersuite c0.14 (GNUTLS_ECDHE_RSA_AES_256_CBC_SHA1)
c: 2 Keeping ciphersuite c0.2f (GNUTLS_ECDHE_RSA_AES_128_GCM_SHA256)
c: 2 Keeping ciphersuite c0.13 (GNUTLS_ECDHE_RSA_AES_128_CBC_SHA1)
c: 2 Keeping ciphersuite 00.9d (GNUTLS_RSA_AES_256_GCM_SHA384)
c: 2 Keeping ciphersuite c0.9d (GNUTLS_RSA_AES_256_CCM)
c: 2 Keeping ciphersuite 00.35 (GNUTLS_RSA_AES_256_CBC_SHA1)
c: 2 Keeping ciphersuite 00.9c (GNUTLS_RSA_AES_128_GCM_SHA256)
c: 2 Keeping ciphersuite c0.9c (GNUTLS_RSA_AES_128_CCM)
c: 2 Keeping ciphersuite 00.2f (GNUTLS_RSA_AES_128_CBC_SHA1)
c: 2 Keeping ciphersuite 00.9f (GNUTLS_DHE_RSA_AES_256_GCM_SHA384)
c: 2 Keeping ciphersuite cc.aa (GNUTLS_DHE_RSA_CHACHA20_POLY1305)
c: 2 Keeping ciphersuite c0.9f (GNUTLS_DHE_RSA_AES_256_CCM)
c: 2 Keeping ciphersuite 00.39 (GNUTLS_DHE_RSA_AES_256_CBC_SHA1)
c: 2 Keeping ciphersuite 00.9e (GNUTLS_DHE_RSA_AES_128_GCM_SHA256)
c: 2 Keeping ciphersuite c0.9e (GNUTLS_DHE_RSA_AES_128_CCM)
c: 2 Keeping ciphersuite 00.33 (GNUTLS_DHE_RSA_AES_128_CBC_SHA1)
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Maximum Record Size/1) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (OCSP Status Request/5) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Sending extension OCSP Status Request/5 (5 bytes)
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Client Certificate Type/19) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Server Certificate Type/20) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Supported Groups/10) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Sent group SECP256R1 (0x17)
c: 4 EXT[0x55a3d4b4ce20]: Sent group SECP384R1 (0x18)
c: 4 EXT[0x55a3d4b4ce20]: Sent group SECP521R1 (0x19)
c: 4 EXT[0x55a3d4b4ce20]: Sent group X25519 (0x1d)
c: 4 EXT[0x55a3d4b4ce20]: Sent group FFDHE2048 (0x100)
c: 4 EXT[0x55a3d4b4ce20]: Sent group FFDHE3072 (0x101)
c: 4 EXT[0x55a3d4b4ce20]: Sent group FFDHE4096 (0x102)
c: 4 EXT[0x55a3d4b4ce20]: Sent group FFDHE6144 (0x103)
c: 4 EXT[0x55a3d4b4ce20]: Sent group FFDHE8192 (0x104)
c: 4 EXT[0x55a3d4b4ce20]: Sending extension Supported Groups/10 (20 bytes)
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Supported EC Point Formats/11) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Sending extension Supported EC Point Formats/11 (2 bytes)
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (SRP/12) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Signature Algorithms/13) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (4.1) RSA-SHA256
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (8.9) RSA-PSS-SHA256
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (8.4) RSA-PSS-RSAE-SHA256
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (4.3) ECDSA-SHA256
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (8.7) EdDSA-Ed25519
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (5.1) RSA-SHA384
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (8.10) RSA-PSS-SHA384
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (8.5) RSA-PSS-RSAE-SHA384
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (5.3) ECDSA-SHA384
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (6.1) RSA-SHA512
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (8.11) RSA-PSS-SHA512
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (8.6) RSA-PSS-RSAE-SHA512
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (6.3) ECDSA-SHA512
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (2.1) RSA-SHA1
c: 4 EXT[0x55a3d4b4ce20]: sent signature algo (2.3) ECDSA-SHA1
c: 4 EXT[0x55a3d4b4ce20]: Sending extension Signature Algorithms/13 (32 bytes)
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (SRTP/14) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Heartbeat/15) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (ALPN/16) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Encrypt-then-MAC/22) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Sending extension Encrypt-then-MAC/22 (0 bytes)
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Extended Master Secret/23) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Sending extension Extended Master Secret/23 (0 bytes)
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Session Ticket/35) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Sending extension Session Ticket/35 (0 bytes)
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Key Share/51) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: sending key share for SECP256R1
c: 4 EXT[0x55a3d4b4ce20]: sending key share for X25519
c: 4 EXT[0x55a3d4b4ce20]: Sending extension Key Share/51 (107 bytes)
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Supported Versions/43) for 'client hello'
c: 2 Advertizing version 3.4
c: 2 Advertizing version 3.3
c: 2 Advertizing version 3.2
c: 2 Advertizing version 3.1
c: 4 EXT[0x55a3d4b4ce20]: Sending extension Supported Versions/43 (9 bytes)
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Post Handshake Auth/49) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Safe Renegotiation/65281) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Sending extension Safe Renegotiation/65281 (1 bytes)
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Server Name Indication/0) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Cookie/44) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Early Data/42) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (PSK Key Exchange Modes/45) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Sending extension PSK Key Exchange Modes/45 (3 bytes)
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Record Size Limit/28) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Sending extension Record Size Limit/28 (2 bytes)
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (ClientHello Padding/21) for 'client hello'
c: 4 EXT[0x55a3d4b4ce20]: Preparing extension (Pre Shared Key/41) for 'client hello'
c: 4 HSK[0x55a3d4b4ce20]: CLIENT HELLO was queued [332 bytes]
c: 3 ASSERT: ../../lib/buffers.c[get_last_packet]:1171
c: 4 HSK[0x55a3d4b4ce20]: SERVER HELLO (2) was received. Length 77[77], frag offset 0, frag length: 77, sequence: 0
c: 3 ASSERT: ../../lib/buffers.c[get_last_packet]:1162
c: 3 ASSERT: ../../lib/buffers.c[_gnutls_handshake_io_recv_int]:1413
c: 4 HSK[0x55a3d4b4ce20]: Server's version: 3.3
c: 4 HSK[0x55a3d4b4ce20]: SessionID length: 32
c: 4 HSK[0x55a3d4b4ce20]: SessionID: f24acd618cd0c7e7df61c00df485a911bc222c29cd9a1d7bcac98861d8558031
c: 4 HSK[0x55a3d4b4ce20]: Selected cipher suite: GNUTLS_RSA_AES_256_CBC_SHA1
c: 4 EXT[0x55a3d4b4ce20]: Parsing extension 'Safe Renegotiation/65281' (1 bytes)
c: 4 HSK[0x55a3d4b4ce20]: Safe renegotiation succeeded
c: 3 ASSERT: ../../lib/buffers.c[get_last_packet]:1171
c: 4 HSK[0x55a3d4b4ce20]: CERTIFICATE (11) was received. Length 980[980], frag offset 0, frag length: 980, sequence: 0
c: INFO Verifying certificate.
c: 3 ASSERT: ../../lib/ocsp-api.c[gnutls_ocsp_status_request_get2]:99
c: 3 ASSERT: ../../../lib/x509/name_constraints.c[gnutls_x509_crt_get_name_constraints]:470
c: INFO The certificate is trusted. 
c: 3 ASSERT: ../../lib/buffers.c[get_last_packet]:1171
c: 4 HSK[0x55a3d4b4ce20]: CERTIFICATE REQUEST (13) was received. Length 125[125], frag offset 0, frag length: 125, sequence: 0
c: 4 EXT[0x55a3d4b4ce20]: rcvd signature algo (4.2) (null)
c: 4 EXT[0x55a3d4b4ce20]: rcvd signature algo (4.1) RSA-SHA256
c: 4 EXT[0x55a3d4b4ce20]: rcvd signature algo (2.1) RSA-SHA1
c: 4 EXT[0x55a3d4b4ce20]: rcvd signature algo (2.2) DSA-SHA1
c: 3 Peer requested CA: CN=Inthe.AM,O=Inthe.AM,C=US
c: 3 ASSERT: ../../lib/buffers.c[get_last_packet]:1171
c: 4 HSK[0x55a3d4b4ce20]: SERVER HELLO DONE (14) was received. Length 0[0], frag offset 0, frag length: 0, sequence: 0
c: 4 HSK[0x55a3d4b4ce20]: CERTIFICATE was queued [950 bytes]
c: 3 ASSERT: ../../../lib/nettle/mpi.c[wrap_nettle_mpi_print]:60
c: 4 HSK[0x55a3d4b4ce20]: CLIENT KEY EXCHANGE was queued [310 bytes]
c: 4 checking cert compat with RSA-SHA256
c: 2 sign handshake cert vrfy: picked RSA-SHA256
c: 3 ASSERT: ../../../lib/nettle/mpi.c[wrap_nettle_mpi_print]:60
c: 4 HSK[0x55a3d4b4ce20]: CERTIFICATE VERIFY was queued [312 bytes]
c: 4 REC[0x55a3d4b4ce20]: Sent ChangeCipherSpec
c: 4 HSK[0x55a3d4b4ce20]: Cipher Suite: GNUTLS_RSA_AES_256_CBC_SHA1
c: 4 HSK[0x55a3d4b4ce20]: Initializing internal [write] cipher sessions
c: 4 HSK[0x55a3d4b4ce20]: recording tls-unique CB (send)
c: 4 HSK[0x55a3d4b4ce20]: FINISHED was queued [16 bytes]
c: 4 HSK[0x55a3d4b4ce20]: Cipher Suite: GNUTLS_RSA_AES_256_CBC_SHA1
c: 3 ASSERT: ../../lib/buffers.c[get_last_packet]:1171
c: 4 HSK[0x55a3d4b4ce20]: FINISHED (20) was received. Length 12[12], frag offset 0, frag length: 12, sequence: 0
c: INFO Handshake was completed: (TLS1.2)-(RSA)-(AES-256-CBC)-(SHA1)
c: INFO Sending 'XXXXclient: task 2.5.1
key: [snip]
org: inthe_am
protocol: v1
type: sync
user: adrien

' (119 bytes)
c: 1 Received packet with illegal length: 16480
c: 3 ASSERT: ../../lib/record.c[recv_headers]:1202
c: 3 ASSERT: ../../lib/record.c[_gnutls_recv_in_buffers]:1271
c: 3 ASSERT: ../../lib/record.c[_gnutls_recv_int]:1656
c: INFO expecting 0 bytes.
c: 3 ASSERT: ../../lib/record.c[check_session_status]:1553
Timer Config::load (/home/adrien/.taskrc) 0.000222 sec
Parse Tree (before command-specifіc processing)
  _original_args
    task rc.debug=1 rc.debug.tls=4 sync
  _args
    word basename='task' raw='task' BINARY 
    pair modifier='debug' name='rc' raw='rc.debug=1' separator='=' value='1' CONFIG ORIGINAL 
    pair modifier='debug.tls' name='rc' raw='rc.debug.tls=4' separator='=' value='4' CONFIG ORIGINAL 
    identifier canonical='synchronize' raw='sync' ORIGINAL CMD ALLOWSMISC 

  pending.data rw - T0000+000~000 L0000+000
completed.data rw - T0000+000~000 L0000+000
     undo.data -- - T0000+000~000 L0000+000
  backlog.data rw - T0000+000~000 L0000+000

Perf task 2.5.1 - 20181212T052632Z init:799 load:0 gc:0 filter:0 commit:63 sort:0 render:0 hooks:22 other:1637759 total:1638643

Syncing with taskwarrior.inthe.am:53589

Configuration override rc.debug:1
Configuration override rc.debug.tls:4
The specified session has been invalidated for some reason.
Sync failed.  Could not connect to the Taskserver.

@kellya's comment is interesting since it indicates that a manual sync sidesteps this issue. I have over 700 tasks that need to be synced; maybe the taskserver is badly behaved in this case? But again, that's a guess.

Edit 1: this is for setting up a new host as well.

Edit 2: manually syncing ~/.task solves the issue for me as well.

MartyLake commented 5 years ago

Just to confirm, manually syncing the dot task folder fixes the issue.

davidgasquez commented 5 years ago

Thanks @MartyLake! That worked but after 4 days I got the same error again.

MartyLake commented 5 years ago

@davidgasquez I'm not alone then ! What's the process of reporting this issue ? I really like TW, and I'm trying to organize myself around it, but my faith in the projects shrinks everytime I encounter these microissues. :(

davidgasquez commented 5 years ago

Perhaps @coddingtonbear knows a bit more about this issue. Keep in mind this is an open source project maintained by him and I'm sure he has lots of things to do!

MartyLake commented 5 years ago

My previous message was quite alarming indeed, and I don't want to undermine the efforts coddingtonbear has poured into this huge project that we use. (thanks!!!!).

coddingtonbear commented 5 years ago

Sorry to let you down, but I'm afraid I have very little to offer on this issue! Inthe.am just uses the normal tasksserver maintained by the folks in #taskwarrior on freenode -- if we're to find an answer, it'd be from them. I assume at least one of you folks has reached out to them to see if they could help you out with troubleshooting steps?

jcrben commented 5 years ago

Where Received packet with illegal length appears in GnuTLS: https://gitlab.com/search?utf8=%E2%9C%93&search=Received+packet+with+illegal+length&group_id=&project_id=179611&search_code=true&repository_ref=master

A search on the issues for GnuTLS turned up nothing a few seemingly irrelevant issues. Nothing in taskserver.

I noticed that @davidgasquez pinged the channel, hopefully someone offers some help but I certainly can't, and haven't hit the issue. may be worth creating an issue in https://gitlab.com/gnutls/gnutls/issues and/or https://github.com/GothenburgBitFactory/taskserver presuming that we don't think it's an inthe.am specific issue? but ideally we would reproduce it on a generic taskserver and try syncing to it from different hosts before doing that...

as I mentioned in the channel:

davidgasquez: I tend to take the brute force approach to debugging - set up a dev environment, build the offender from source. maybe set up a debugger. not really clever enough to do it any other way. but self-hosting inthe.am isn't automated right now. I've got the dev env of inthe.am working if you want to join me in their gitter chatroom

davidgasquez commented 5 years ago

Thanks for getting back @jcrben. I closed the IRC tab after a while assuming I wasn't going to get an answer, my bad!

I think it might be a good starting point to create a new issue in the official taskserver repository.

That said, since my last message I copied the .task folder from another computer and seems to be working smoothly. If I get the error again, I'll try your approach of brute force debugging.

Thanks again for helping and getting back via Github instead of leaving the message on IRC.

adrienthebo commented 5 years ago

I've built a debug copy of taskwarrior and have been using it to single step through the issue, and I'm pretty sure there's something very odd going on with TLS. The TLS maximum record size is 16K, and per the GnuTLS error, we're receiving TLS records that are greater than that.

I've single stepped to gnutls_record_receive function; when we step into that function gnutls aborts the process:

c: 10 READ: Got 5 bytes from 0x3
c: 10 READ: read 5 bytes from 0x3
c: 10 RB: Have 0 bytes into buffer. Adding 5 bytes.
c: 10 RB: Requested 5 bytes
c: 5 REC[0x56424f728cc0]: SSL 3.3 Application Data packet received. Epoch 1, length: 16576
c: 1 Received packet with illegal length: 16576
c: 3 ASSERT: ../../lib/record.c[recv_headers]:1202
c: 3 ASSERT: ../../lib/record.c[_gnutls_recv_in_buffers]:1271
c: 3 ASSERT: ../../lib/record.c[_gnutls_recv_int]:1656
c: INFO expecting 0 bytes.
c: 3 ASSERT: ../../lib/record.c[check_session_status]:1553
c: 5 REC[0x56424f728cc0]: Start of epoch cleanup
c: 5 REC[0x56424f728cc0]: End of epoch cleanup
c: 5 REC[0x56424f728cc0]: Epoch #1 freed

Of specific note is SSL 3.3 Application Data packet received. Epoch 1, length: 16576 - that record length is 192 bytes too long.

I can fire up wireshark at some point and start picking apart the TLS stream to see if the record on the wire is too large, but this seems like something is subtly screwed up with the TLS sessions.

Here's my end of things, config wise: 

╰─ task diagnostics

task 2.5.1
   Platform: Linux

Compiler
    Version: 7.2.0
       Caps: +stdc +stdc_hosted +LP64 +c8 +i32 +l64 +vp64 +time_t64
 Compliance: C++11

Build Features
      CMake: 3.9.5
    libuuid: libuuid + uuid_unparse_lower
  libgnutls: 3.5.8
 Build type: None

Configuration
       File: /home/adrien/.taskrc (found), 2272 bytes, mode 100644
       Data: /home/adrien/.task (found), dir, mode 40755
    Locking: Enabled
         GC: Enabled
    $VISUAL: vim
     Server: taskwarrior.inthe.am:53589
         CA: ~/.config/taskwarrior/ca.cert.pem, readable, 2405 bytes
      Trust: ignore hostname
Certificate: ~/.config/taskwarrior/private.certificate.pem, readable, 2462 bytes
        Key: ~/.config/taskwarrior/private.key.pem, readable, 3664 bytes
    Ciphers: NORMAL
      Creds: inthe_am/adrien/************************************

Hooks
     System: Enabled
   Location: /home/adrien/.task/hooks
             (-none-)

Tests
      $TERM: screen-256color (211x111)
       Dups: Scanned 0 tasks for duplicate UUIDs:
             No duplicates found
 Broken ref: Scanned 0 tasks for broken references:
             No broken references found

╰─ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 18.10
Release:        18.10
Codename:       cosmic

@coddingtonbear could you check which version of gnutls the taskd server is compiled against?

One final note that might be of use - GnuTLS implements random additional padding to prevent statistical analysis of traffic. This is purely a hunch but if we were adding extra padding on the records, that might have pushed us over the record size.

Edit - it's 12:40am, apologies for mangled grammar/spelling.

adrienthebo commented 5 years ago

I just got taskwarrior to sync by enabling compatibility mode in GnuTLS:

task rc.debug=1 rc.debug.tls=10 'rc.taskd.ciphers=NORMAL:%COMPAT' sync

If anyone could give that command a shot to see if it remediates this issue, I'd be obliged.

kellya commented 5 years ago

@adrienthebo That seems to work for me. I got the error on sync, re-ran it with the 'rc.taskd.ciphers=NORMAL:%COMPAT' and it worked.

adrienthebo commented 5 years ago

@kellya awesome, glad to hear it. While enabling compatibility mode isn't the most ideal solution, it'll work in the meantime.

Out of curiosity, have you had this issue with multiple ISPs? I have comcast and it's possible that they're twiddling with my TLS traffic, is there a chance that your network connection is being modified by your carrier? If we can determine if this is an issue with traffic in transit vs the taskwarrior server, that'll help determine a fix.

And for my edification, could you post the result of task diagnostics?

celadevra commented 5 years ago

@adrienthebo Works for me too. I observe the issue using China Unicom and another smaller local ISP, but I'm in China so the possibility of ISPs modifying connection cannot be ruled out.

After one successful task 'rc.taskd.ciphers=NORMAL:%COMPAT' sync init I can use the default options for syncing with no problem.

$ task rc.debug=1 rc.debug.tls=2 sync
c: INFO Server certificate will be verified but hostname ignored.
c: 2 added 6 protocols, 29 ciphersuites, 18 sig algos and 9 groups into priority list
c: 2 Keeping ciphersuite 13.02 (GNUTLS_AES_256_GCM_SHA384)
c: 2 Keeping ciphersuite 13.03 (GNUTLS_CHACHA20_POLY1305_SHA256)
c: 2 Keeping ciphersuite 13.01 (GNUTLS_AES_128_GCM_SHA256)
c: 2 Keeping ciphersuite 13.04 (GNUTLS_AES_128_CCM_SHA256)
c: 2 Keeping ciphersuite c0.2c (GNUTLS_ECDHE_ECDSA_AES_256_GCM_SHA384)
c: 2 Keeping ciphersuite cc.a9 (GNUTLS_ECDHE_ECDSA_CHACHA20_POLY1305)
c: 2 Keeping ciphersuite c0.ad (GNUTLS_ECDHE_ECDSA_AES_256_CCM)
c: 2 Keeping ciphersuite c0.0a (GNUTLS_ECDHE_ECDSA_AES_256_CBC_SHA1)
c: 2 Keeping ciphersuite c0.2b (GNUTLS_ECDHE_ECDSA_AES_128_GCM_SHA256)
c: 2 Keeping ciphersuite c0.ac (GNUTLS_ECDHE_ECDSA_AES_128_CCM)
c: 2 Keeping ciphersuite c0.09 (GNUTLS_ECDHE_ECDSA_AES_128_CBC_SHA1)
c: 2 Keeping ciphersuite c0.30 (GNUTLS_ECDHE_RSA_AES_256_GCM_SHA384)
c: 2 Keeping ciphersuite cc.a8 (GNUTLS_ECDHE_RSA_CHACHA20_POLY1305)
c: 2 Keeping ciphersuite c0.14 (GNUTLS_ECDHE_RSA_AES_256_CBC_SHA1)
c: 2 Keeping ciphersuite c0.2f (GNUTLS_ECDHE_RSA_AES_128_GCM_SHA256)
c: 2 Keeping ciphersuite c0.13 (GNUTLS_ECDHE_RSA_AES_128_CBC_SHA1)
c: 2 Keeping ciphersuite 00.9d (GNUTLS_RSA_AES_256_GCM_SHA384)
c: 2 Keeping ciphersuite c0.9d (GNUTLS_RSA_AES_256_CCM)
c: 2 Keeping ciphersuite 00.35 (GNUTLS_RSA_AES_256_CBC_SHA1)
c: 2 Keeping ciphersuite 00.9c (GNUTLS_RSA_AES_128_GCM_SHA256)
c: 2 Keeping ciphersuite c0.9c (GNUTLS_RSA_AES_128_CCM)
c: 2 Keeping ciphersuite 00.2f (GNUTLS_RSA_AES_128_CBC_SHA1)
c: 2 Keeping ciphersuite 00.9f (GNUTLS_DHE_RSA_AES_256_GCM_SHA384)
c: 2 Keeping ciphersuite cc.aa (GNUTLS_DHE_RSA_CHACHA20_POLY1305)
c: 2 Keeping ciphersuite c0.9f (GNUTLS_DHE_RSA_AES_256_CCM)
c: 2 Keeping ciphersuite 00.39 (GNUTLS_DHE_RSA_AES_256_CBC_SHA1)
c: 2 Keeping ciphersuite 00.9e (GNUTLS_DHE_RSA_AES_128_GCM_SHA256)
c: 2 Keeping ciphersuite c0.9e (GNUTLS_DHE_RSA_AES_128_CCM)
c: 2 Keeping ciphersuite 00.33 (GNUTLS_DHE_RSA_AES_128_CBC_SHA1)
c: 2 Advertizing version 3.4
c: 2 Advertizing version 3.3
c: 2 Advertizing version 3.2
c: 2 Advertizing version 3.1
c: INFO Verifying certificate.
c: INFO The certificate is trusted. 
c: 2 sign handshake cert vrfy: picked RSA-SHA256
c: INFO Handshake was completed: (TLS1.2)-(RSA)-(AES-256-CBC)-(SHA1)
c: INFO Sending 'XXXXclient: task 2.5.1
key: [...]
org: inthe_am
protocol: v1
type: sync
user:
[...]

' (157 bytes)
c: INFO expecting 91 bytes.
c: INFO Receiving 'XXXXclient: taskd 1.1.0
code: 201
status: No change
[...]
Syncing with taskwarrior.inthe.am:53589
$ task diagnostics

task 2.5.1
   Platform: Linux

Compiler
    Version: 8.2.1 20181105 (Red Hat 8.2.1-5)
       Caps: +stdc +stdc_hosted +LP64 +c8 +i32 +l64 +vp64 +time_t64
 Compliance: C++11

Build Features
      Built: Nov 28 2018 10:10:19
      CMake: 3.12.1
    libuuid: libuuid + uuid_unparse_lower
  libgnutls: 3.6.4
 Build type: 

Configuration
       File: /home/xhy/.taskrc (found), 1558 bytes, mode 100664
       Data: /home/xhy/.task (found), dir, mode 40755
    Locking: Enabled
         GC: Enabled
     Server: taskwarrior.inthe.am:53589
         CA: /home/xhy/.task/ca.cert.pem, readable, 2405 bytes
      Trust: ignore hostname
Certificate: /home/xhy/.task/private.certificate.pem, readable, 2462 bytes
        Key: /home/xhy/.task/private.key.pem, readable, 3664 bytes
    Ciphers: NORMAL
      Creds: inthe_am/haoyang/************************************

Hooks
     System: Enabled
   Location: /home/xhy/.task/hooks
             (-none-)

Tests
      $TERM: xterm-256color (120x30)
       Dups: Scanned 580 tasks for duplicate UUIDs:
             No duplicates found
 Broken ref: Scanned 580 tasks for broken references:
             No broken references found
coddingtonbear commented 5 years ago

It looks like you found the answer, @adrienthebo -- that's some very impressive debugging; thanks for spending so much time digging! Hopefully that information will be helpful to the folks who maintain the taskserver (https://github.com/GothenburgBitFactory/taskserver); did any of you folks happen to report this issue to them?

In case it still might be helpful; it looks like the version of GnuTLS I'm using is 3.0.11, but given that I'll have to spend some time upgrading Ubuntu soon (the LTS I'm using is EOL'd in just a couple weeks), that version is likely to change very soon.

coddingtonbear commented 5 years ago

Just a little while ago ago completed a distribution upgrade; so now the version of GnuTLS in use by the Taskserver on Inthe.AM is 3.4.10.

rolandog commented 5 years ago

Hello.

Thanks @coddingtonbear for the great service and for the upgrade. Also, thanks to @adrienthebo for his insightful debugging.

I unfortunately started getting a this error message just today; I'm at a loss as to what could be the cause, and would be very grateful for some feedback.

Here's my output of the logs:

task sync output: ``` Syncing with taskwarrior.inthe.am:53589 The specified session has been invalidated for some reason. Sync failed. Could not connect to the Taskserver. ```
task 'rc.taskd.ciphers=NORMAL:%COMPAT' sync init output: ``` task 'rc.taskd.ciphers=NORMAL:%COMPAT' sync init Please confirm that you wish to upload all your pending tasks to the Taskserver (yes/no) Y Syncing with taskwarrior.inthe.am:53589 Configuration override rc.taskd.ciphers:NORMAL:%COMPAT The specified session has been invalidated for some reason. Sync failed. Could not connect to the Taskserver. ```

With a moderate level of debugging enabled (I can post a higher level, but -- apart from explicit printed secrets -- is there anything else that should be censored before pasting?)

task rc.debug=1 rc.debug.tls=2 sync output: ``` c: INFO Server certificate will be verified but hostname ignored. c: INFO Verifying certificate. c: INFO The certificate is trusted. c: 2 received curve SECP256R1 c: 2 sign handshake cert vrfy: picked RSA-SHA256 with SHA256 c: INFO Handshake was completed: (TLS1.2)-(ECDHE-RSA-SECP256R1)-(AES-256-GCM) c: INFO Sending 'XXXXclient: task 2.5.1 key: [...] org: inthe_am protocol: v1 type: sync user: [...] ' (121 bytes) c: INFO expecting 0 bytes. [...] Syncing with taskwarrior.inthe.am:53589 Configuration override rc.debug:1 Configuration override rc.debug.tls:2 The specified session has been invalidated for some reason. Sync failed. Could not connect to the Taskserver. ```

And, finally, environment information.

task diag on work laptop output: ``` task 2.5.1 Platform: Linux Compiler Version: 7.2.0 Caps: +stdc +stdc_hosted +LP64 +c8 +i32 +l64 +vp64 +time_t64 Compliance: C++11 Build Features CMake: 3.9.5 libuuid: libuuid + uuid_unparse_lower libgnutls: 3.5.8 Build type: None Configuration File: /home/rolandog/.taskrc (found), 2190 bytes, mode 100644 Data: /home/rolandog/.task (found), dir, mode 40755 Locking: Enabled GC: Enabled Server: taskwarrior.inthe.am:53589 CA: /home/rolandog/.taskd/certs/inthe_am/ca.cert.pem, readable, 2405 bytes Trust: ignore hostname Certificate: /home/rolandog/.taskd/certs/inthe_am/private.certificate.pem, readable, 2462 bytes Key: /home/rolandog/.taskd/certs/inthe_am/private.key.pem, readable, 3660 bytes Ciphers: NORMAL Creds: inthe_am/rolandog/************************************ Hooks System: Enabled Location: /home/rolandog/.task/hooks Active: on-add.blocks_attr.py (executable) (symlink) on-launch.blocks_attr.py (executable) (symlink) on-modify.blocks_attr.py (executable) Inactive: Tests $TERM: xterm-256color (323x67) Dups: Scanned 947 tasks for duplicate UUIDs: No duplicates found Broken ref: Scanned 947 tasks for broken references: No broken references found ```
lsb_release -a on work laptop output: ``` No LSB modules are available. Distributor ID: Ubuntu Description: Ubuntu 18.04.2 LTS Release: 18.04 Codename: bionic ```

I also started getting some 'ERROR: Malformed Message' errors on the TaskwarriorC2 app I use on Android.

Again, thanks in advance for any input!

coddingtonbear commented 5 years ago

Interestingly, me, too, @rolandog; I just restarted the service, though, and now it seems to be happy again. I'm... not sure.

kellya commented 5 years ago

Yep.  I just saw the same.  I changed nothing and started getting "The specified session has been invalidated for some reason. Sync failed.  Could not connect to the Taskserver.".  I ran task sync 5 times in a row changing nothing in between. It failed 4 times, and then suddenly just worked on the last time and now on every sync since.  I'll try to issue a sync with logging that could actually be helpful next time.

On 3/20/19 1:45 PM, rolandog wrote:

Hello.

Thanks @coddingtonbear https://github.com/coddingtonbear for the great service and for the upgrade. Also, thanks to @adrienthebo https://github.com/adrienthebo for his insightful debugging.

I unfortunately started getting a this error message just today; I'm at a loss as to what could be the cause, and would be very grateful for some feedback.

Here's my output of the logs:

|task sync| output: |Syncing with taskwarrior.inthe.am:53589 The specified session has been invalidated for some reason. Sync failed. Could not connect to the Taskserver. | |task 'rc.taskd.ciphers=NORMAL:%COMPAT' sync init| output: |task 'rc.taskd.ciphers=NORMAL:%COMPAT' sync init Please confirm that you wish to upload all your pending tasks to the Taskserver (yes/no) Y Syncing with taskwarrior.inthe.am:53589 Configuration override rc.taskd.ciphers:NORMAL:%COMPAT The specified session has been invalidated for some reason. Sync failed. Could not connect to the Taskserver. |

With a moderate level of debugging enabled (I can post a higher level, but -- apart from explicit printed secrets -- is there anything else that should be censored before pasting?)

|task rc.debug=1 rc.debug.tls=2 sync| output: |c: INFO Server certificate will be verified but hostname ignored. c: INFO Verifying certificate. c: INFO The certificate is trusted. c: 2 received curve SECP256R1 c: 2 sign handshake cert vrfy: picked RSA-SHA256 with SHA256 c: INFO Handshake was completed: (TLS1.2)-(ECDHE-RSA-SECP256R1)-(AES-256-GCM) c: INFO Sending 'XXXXclient: task 2.5.1 key: [...] org: inthe_am protocol: v1 type: sync user: [...] ' (121 bytes) c: INFO expecting 0 bytes. [...] Syncing with taskwarrior.inthe.am:53589 Configuration override rc.debug:1 Configuration override rc.debug.tls:2 The specified session has been invalidated for some reason. Sync failed. Could not connect to the Taskserver. |

And, finally, environment information.

|task diag| on work laptop output: |task 2.5.1 Platform: Linux Compiler Version: 7.2.0 Caps: +stdc +stdc_hosted +LP64 +c8 +i32 +l64 +vp64 +time_t64 Compliance: C++11 Build Features CMake: 3.9.5 libuuid: libuuid + uuid_unparse_lower libgnutls: 3.5.8 Build type: None Configuration File: /home/rolandog/.taskrc (found), 2190 bytes, mode 100644 Data: /home/rolandog/.task (found), dir, mode 40755 Locking: Enabled GC: Enabled Server: taskwarrior.inthe.am:53589 CA: /home/rolandog/.taskd/certs/inthe_am/ca.cert.pem, readable, 2405 bytes Trust: ignore hostname Certificate: /home/rolandog/.taskd/certs/inthe_am/private.certificate.pem, readable, 2462 bytes Key: /home/rolandog/.taskd/certs/inthe_am/private.key.pem, readable, 3660 bytes Ciphers: NORMAL Creds: inthe_am/rolandog/**** Hooks System: Enabled Location: /home/rolandog/.task/hooks Active: on-add.blocks_attr.py (executable) (symlink) on-launch.blocks_attr.py (executable) (symlink) on-modify.blocks_attr.py (executable) Inactive: Tests $TERM: xterm-256color (323x67) Dups: Scanned 947 tasks for duplicate UUIDs: No duplicates found Broken ref: Scanned 947 tasks for broken references: No broken references found | |lsb_release -a| on work laptop output: |No LSB modules are available. Distributor ID: Ubuntu Description: Ubuntu 18.04.2 LTS Release: 18.04 Codename: bionic |

I also started getting some 'ERROR: Malformed Message' errors on the TaskwarriorC2 app I use on Android.

Again, thanks in advance for any input!

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/coddingtonbear/inthe.am/issues/301#issuecomment-474953451, or mute the thread https://github.com/notifications/unsubscribe-auth/AAKQuGujl0rRyAjI4749_EceiGIxkrvhks5vYnO9gaJpZM4XUmde.

coddingtonbear commented 5 years ago

Looking at the logs, it appears to have began happening immediately after a sync by somebody who has a particularly huge task list:

2019-03-20 13:29:52 [904] Loaded 90062 records
2019-03-20 13:30:01 [904] Subset 77008 tasks
2019-03-20 13:30:01 [904] Stored 0 tasks, merged 0 tasks

I'm fairly sure that's in at least the 99th percentile of task list sizes, so there're a few things to look into from here.

adrienthebo commented 5 years ago

I finally got around to firing up wireshark and picking apart some SSL traces to chase down the root of the long reads, but it looks like the GnuTLS upgrade solved the issue that I was running into. @coddingtonbear cheers!

@rolandog @kellya I'd love to get more in depth logs from you with debug.tls=10; the information in those logs might help me reproduce your exact issue. Everything up until c: INFO Handshake was completed: [...] Should be horribly abstruse TLS logging, and should be safe to share here. The only thing that's particularly sensitive looking is the key field that's transmitted after the handshake, but I think that's the only thing to look for. If you could provide the log dumps with the key redacted I'd be grateful. (Though of course I'm some random chap on the Internet so please take another review of your logs before sharing.)

@rolandog the really interesting thing is c: INFO expecting 0 bytes. - I think that means that you got a zero length TLS record, which implies some very strange TLS shenanigans. If you consistently get expected zero bytes before a failure, then that's probably the culprit.

@kellya per the above comments, definitely keep an eye any line mentioning the number of expected bytes, that'll be highly informative.

EDIT: After reviewing my own logs it looks like the plaintext of the sync will be dumped in cleartext, so watch out for that. However this only pops up on a successful sync (I think?) so if task sync is working then the logs won't contain anything worth debugging.

xrs444 commented 5 years ago

Hello, I actually fired this back up just before you did the patching and saw the error, but the workaround cleared it. Since the patching it seems to be OK for me, but I can run any diags you need if that will help.

aprosaist commented 5 years ago

@coddingtonbear I can confirm that this is happening to me as well as of this evening. I've been using TW and ITAM together for quite some time now with no hiccups ever until now. I tried running the compatibility mode command, but no dice. I also tested on my other devices, but I'm receiving the error on all of them. Finally, I tested the web interface, and although it allows me to interact with my tasks, it is also throwing the same error message on some operations (mostly when deleting tasks).

I know it's probably a long shot, but do you (or anyone else watching this thread) have any ideas by chance? It's a bummer because I'm kind of dead in the water without my task list available.

morganmay commented 5 years ago

I am experiencing this same issue with taskwarrior 2.5.1. Syncing works occasionally, but fails more often than not. I haven't noticed a patter to when it works and when it doesn't. The only thing turned up by task diagnostics was a task with a duplicate UUID - I have no idea if that's relevant. The Android app throws the same "ERROR: Malformed Message" that @rolandog mentioned.

echo-bravo-yahoo commented 5 years ago

Also experiencing this as of today! I'm probably 0/60 on sync attempts working w/taskwarrior 2.5.1. It worked reliably until very recently. As to the discussion above about SSL, running in compatibility mode etc (task rc.debug=1 rc.debug.tls=10 rc.taskd.ciphers=NORMAL:%COMPAT sync) doesn't appear to help. I do, however, see INFO expecting 0 bytes. shortly before the end of the TLS debug.

Here's the output: ``` task rc.debug=1 rc.debug.tls=10 'rc.taskd.ciphers=NORMAL:%COMPAT' sync c: INFO Server certificate will be verified but hostname ignored. c: 3 ASSERT: extensions.c[_gnutls_get_extension]:65 c: 3 ASSERT: extensions.c[_gnutls_get_extension]:65 c: 3 ASSERT: mpi.c[_gnutls_x509_read_uint]:246 c: 3 ASSERT: extensions.c[_gnutls_get_extension]:65 c: 3 ASSERT: extensions.c[_gnutls_get_extension]:65 c: 3 ASSERT: x509_ext.c[gnutls_subject_alt_names_get]:110 c: 3 ASSERT: x509.c[get_alt_name]:1701 c: 3 ASSERT: extensions.c[_gnutls_get_extension]:65 c: 5 REC[0x7fe8f9809200]: Allocating epoch #0 c: 3 ASSERT: constate.c[_gnutls_epoch_get]:600 c: 5 REC[0x7fe8f9809200]: Allocating epoch #1 c: 4 HSK[0x7fe8f9809200]: Adv. version: 3.3 c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_ECDSA_AES_256_GCM_SHA384 (C0.2C) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_ECDSA_CAMELLIA_256_GCM_SHA384 (C0.87) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_ECDSA_CHACHA20_POLY1305 (CC.A9) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_ECDSA_AES_256_CCM (C0.AD) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_ECDSA_AES_256_CBC_SHA1 (C0.0A) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_ECDSA_AES_256_CBC_SHA384 (C0.24) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_ECDSA_CAMELLIA_256_CBC_SHA384 (C0.73) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_ECDSA_AES_128_GCM_SHA256 (C0.2B) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_ECDSA_CAMELLIA_128_GCM_SHA256 (C0.86) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_ECDSA_AES_128_CCM (C0.AC) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_ECDSA_AES_128_CBC_SHA1 (C0.09) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_ECDSA_AES_128_CBC_SHA256 (C0.23) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_ECDSA_CAMELLIA_128_CBC_SHA256 (C0.72) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_ECDSA_3DES_EDE_CBC_SHA1 (C0.08) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_AES_256_GCM_SHA384 (C0.30) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_CAMELLIA_256_GCM_SHA384 (C0.8B) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_CHACHA20_POLY1305 (CC.A8) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_AES_256_CBC_SHA1 (C0.14) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_AES_256_CBC_SHA384 (C0.28) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_CAMELLIA_256_CBC_SHA384 (C0.77) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_AES_128_GCM_SHA256 (C0.2F) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_CAMELLIA_128_GCM_SHA256 (C0.8A) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_AES_128_CBC_SHA1 (C0.13) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_AES_128_CBC_SHA256 (C0.27) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_CAMELLIA_128_CBC_SHA256 (C0.76) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_ECDHE_RSA_3DES_EDE_CBC_SHA1 (C0.12) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_AES_256_GCM_SHA384 (00.9D) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_CAMELLIA_256_GCM_SHA384 (C0.7B) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_AES_256_CCM (C0.9D) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_AES_256_CBC_SHA1 (00.35) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_AES_256_CBC_SHA256 (00.3D) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_CAMELLIA_256_CBC_SHA1 (00.84) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_CAMELLIA_256_CBC_SHA256 (00.C0) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_AES_128_GCM_SHA256 (00.9C) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_CAMELLIA_128_GCM_SHA256 (C0.7A) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_AES_128_CCM (C0.9C) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_AES_128_CBC_SHA1 (00.2F) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_AES_128_CBC_SHA256 (00.3C) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_CAMELLIA_128_CBC_SHA1 (00.41) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_CAMELLIA_128_CBC_SHA256 (00.BA) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_RSA_3DES_EDE_CBC_SHA1 (00.0A) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_256_GCM_SHA384 (00.9F) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_CAMELLIA_256_GCM_SHA384 (C0.7D) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_CHACHA20_POLY1305 (CC.AA) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_256_CCM (C0.9F) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_256_CBC_SHA1 (00.39) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_256_CBC_SHA256 (00.6B) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_CAMELLIA_256_CBC_SHA1 (00.88) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_CAMELLIA_256_CBC_SHA256 (00.C4) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_128_GCM_SHA256 (00.9E) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_CAMELLIA_128_GCM_SHA256 (C0.7C) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_128_CCM (C0.9E) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_128_CBC_SHA1 (00.33) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_AES_128_CBC_SHA256 (00.67) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_CAMELLIA_128_CBC_SHA1 (00.45) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_CAMELLIA_128_CBC_SHA256 (00.BE) c: 4 HSK[0x7fe8f9809200]: Keeping ciphersuite: GNUTLS_DHE_RSA_3DES_EDE_CBC_SHA1 (00.16) c: 4 EXT[0x7fe8f9809200]: Sending extension OCSP Status Request (5 bytes) c: 4 EXT[0x7fe8f9809200]: Sending extension Safe Renegotiation (1 bytes) c: 4 EXT[0x7fe8f9809200]: Sending extension Session Ticket (0 bytes) c: 4 EXT[0x7fe8f9809200]: Sending extension Supported curves (12 bytes) c: 4 EXT[0x7fe8f9809200]: Sending extension Supported ECC Point Formats (2 bytes) c: 4 EXT[0x7fe8f9809200]: sent signature algo (4.1) RSA-SHA256 c: 4 EXT[0x7fe8f9809200]: sent signature algo (4.3) ECDSA-SHA256 c: 4 EXT[0x7fe8f9809200]: sent signature algo (5.1) RSA-SHA384 c: 4 EXT[0x7fe8f9809200]: sent signature algo (5.3) ECDSA-SHA384 c: 4 EXT[0x7fe8f9809200]: sent signature algo (6.1) RSA-SHA512 c: 4 EXT[0x7fe8f9809200]: sent signature algo (6.3) ECDSA-SHA512 c: 4 EXT[0x7fe8f9809200]: sent signature algo (3.1) RSA-SHA224 c: 4 EXT[0x7fe8f9809200]: sent signature algo (3.3) ECDSA-SHA224 c: 4 EXT[0x7fe8f9809200]: sent signature algo (2.1) RSA-SHA1 c: 4 EXT[0x7fe8f9809200]: sent signature algo (2.3) ECDSA-SHA1 c: 4 EXT[0x7fe8f9809200]: Sending extension Signature Algorithms (22 bytes) c: 4 HSK[0x7fe8f9809200]: CLIENT HELLO was queued [225 bytes] c: 5 REC[0x7fe8f9809200]: Preparing Packet Handshake(22) with length: 225 and min pad: 0 c: 9 ENC[0x7fe8f9809200]: cipher: NULL, MAC: MAC-NULL, Epoch: 0 c: 5 REC[0x7fe8f9809200]: Sent Packet[1] Handshake(22) in epoch 0 and length: 230 c: 3 ASSERT: buffers.c[get_last_packet]:1159 c: 10 READ: Got 5 bytes from 0x5 c: 10 READ: read 5 bytes from 0x5 c: 10 RB: Have 0 bytes into buffer. Adding 5 bytes. c: 10 RB: Requested 5 bytes c: 5 REC[0x7fe8f9809200]: SSL 3.3 Handshake packet received. Epoch 0, length: 87 c: 5 REC[0x7fe8f9809200]: Expected Packet Handshake(22) c: 5 REC[0x7fe8f9809200]: Received Packet Handshake(22) with length: 87 c: 10 READ: Got 87 bytes from 0x5 c: 10 READ: read 87 bytes from 0x5 c: 10 RB: Have 5 bytes into buffer. Adding 87 bytes. c: 10 RB: Requested 92 bytes c: 5 REC[0x7fe8f9809200]: Decrypted Packet[0] Handshake(22) with length: 87 c: 4 HSK[0x7fe8f9809200]: SERVER HELLO (2) was received. Length 83[83], frag offset 0, frag length: 83, sequence: 0 c: 4 HSK[0x7fe8f9809200]: Server's version: 3.3 c: 4 HSK[0x7fe8f9809200]: SessionID length: 32 c: 4 HSK[0x7fe8f9809200]: SessionID: REDACTED c: 4 HSK[0x7fe8f9809200]: Selected cipher suite: ECDHE_RSA_AES_256_GCM_SHA384 c: 4 HSK[0x7fe8f9809200]: Selected compression method: NULL (0) c: 4 EXT[0x7fe8f9809200]: Parsing extension 'Safe Renegotiation/65281' (1 bytes) c: 4 EXT[0x7fe8f9809200]: Parsing extension 'Supported ECC Point Formats/11' (2 bytes) c: 4 HSK[0x7fe8f9809200]: Safe renegotiation succeeded c: 3 ASSERT: buffers.c[get_last_packet]:1159 c: 10 READ: Got 5 bytes from 0x5 c: 10 READ: read 5 bytes from 0x5 c: 10 RB: Have 0 bytes into buffer. Adding 5 bytes. c: 10 RB: Requested 5 bytes c: 5 REC[0x7fe8f9809200]: SSL 3.3 Handshake packet received. Epoch 0, length: 984 c: 5 REC[0x7fe8f9809200]: Expected Packet Handshake(22) c: 5 REC[0x7fe8f9809200]: Received Packet Handshake(22) with length: 984 c: 10 READ: Got 984 bytes from 0x5 c: 10 READ: read 984 bytes from 0x5 c: 10 RB: Have 5 bytes into buffer. Adding 984 bytes. c: 10 RB: Requested 989 bytes c: 5 REC[0x7fe8f9809200]: Decrypted Packet[1] Handshake(22) with length: 984 c: 4 HSK[0x7fe8f9809200]: CERTIFICATE (11) was received. Length 980[980], frag offset 0, frag length: 980, sequence: 0 c: 3 ASSERT: extensions.c[_gnutls_get_extension]:65 c: INFO Verifying certificate. c: 3 ASSERT: extensions.c[_gnutls_get_extension]:65 c: 3 ASSERT: status_request.c[gnutls_ocsp_status_request_get]:379 c: 3 ASSERT: extensions.c[_gnutls_get_extension]:65 c: 3 ASSERT: dn.c[_gnutls_x509_compare_raw_dn]:1003 c: 3 ASSERT: common.c[x509_read_value]:698 c: 3 ASSERT: extensions.c[_gnutls_get_extension]:65 c: 3 ASSERT: name_constraints.c[gnutls_x509_crt_get_name_constraints]:470 c: 3 ASSERT: extensions.c[_gnutls_get_extension]:65 c: 3 ASSERT: mpi.c[_gnutls_x509_read_uint]:246 c: INFO The certificate is trusted. c: 3 ASSERT: buffers.c[get_last_packet]:1159 c: 10 READ: Got 5 bytes from 0x5 c: 10 READ: read 5 bytes from 0x5 c: 10 RB: Have 0 bytes into buffer. Adding 5 bytes. c: 10 RB: Requested 5 bytes c: 5 REC[0x7fe8f9809200]: SSL 3.3 Handshake packet received. Epoch 0, length: 381 c: 5 REC[0x7fe8f9809200]: Expected Packet Handshake(22) c: 5 REC[0x7fe8f9809200]: Received Packet Handshake(22) with length: 381 c: 10 READ: Got 272 bytes from 0x5 c: 10 READ: Got 109 bytes from 0x5 c: 10 READ: read 381 bytes from 0x5 c: 10 RB: Have 5 bytes into buffer. Adding 381 bytes. c: 10 RB: Requested 386 bytes c: 5 REC[0x7fe8f9809200]: Decrypted Packet[2] Handshake(22) with length: 381 c: 4 HSK[0x7fe8f9809200]: SERVER KEY EXCHANGE (12) was received. Length 377[377], frag offset 0, frag length: 377, sequence: 0 c: 2 received curve SECP256R1 c: 4 HSK[0x7fe8f9809200]: Selected ECC curve SECP256R1 (2) c: 3 ASSERT: extensions.c[_gnutls_get_extension]:65 c: 4 HSK[0x7fe8f9809200]: verify handshake data: using RSA-SHA256 c: 3 ASSERT: buffers.c[get_last_packet]:1159 c: 10 READ: Got 5 bytes from 0x5 c: 10 READ: read 5 bytes from 0x5 c: 10 RB: Have 0 bytes into buffer. Adding 5 bytes. c: 10 RB: Requested 5 bytes c: 5 REC[0x7fe8f9809200]: SSL 3.3 Handshake packet received. Epoch 0, length: 87 c: 5 REC[0x7fe8f9809200]: Expected Packet Handshake(22) c: 5 REC[0x7fe8f9809200]: Received Packet Handshake(22) with length: 87 c: 10 READ: Got 87 bytes from 0x5 c: 10 READ: read 87 bytes from 0x5 c: 10 RB: Have 5 bytes into buffer. Adding 87 bytes. c: 10 RB: Requested 92 bytes c: 5 REC[0x7fe8f9809200]: Decrypted Packet[3] Handshake(22) with length: 87 c: 4 HSK[0x7fe8f9809200]: CERTIFICATE REQUEST (13) was received. Length 83[83], frag offset 0, frag length: 83, sequence: 0 c: 4 EXT[0x7fe8f9809200]: rcvd signature algo (4.1) RSA-SHA256 c: 4 EXT[0x7fe8f9809200]: rcvd signature algo (4.3) ECDSA-SHA256 c: 4 EXT[0x7fe8f9809200]: rcvd signature algo (5.1) RSA-SHA384 c: 4 EXT[0x7fe8f9809200]: rcvd signature algo (5.3) ECDSA-SHA384 c: 4 EXT[0x7fe8f9809200]: rcvd signature algo (6.1) RSA-SHA512 c: 4 EXT[0x7fe8f9809200]: rcvd signature algo (6.3) ECDSA-SHA512 c: 4 EXT[0x7fe8f9809200]: rcvd signature algo (3.1) RSA-SHA224 c: 4 EXT[0x7fe8f9809200]: rcvd signature algo (3.3) ECDSA-SHA224 c: 4 EXT[0x7fe8f9809200]: rcvd signature algo (2.1) RSA-SHA1 c: 4 EXT[0x7fe8f9809200]: rcvd signature algo (2.3) ECDSA-SHA1 c: 3 ASSERT: buffers.c[get_last_packet]:1159 c: 10 READ: Got 5 bytes from 0x5 c: 10 READ: read 5 bytes from 0x5 c: 10 RB: Have 0 bytes into buffer. Adding 5 bytes. c: 10 RB: Requested 5 bytes c: 5 REC[0x7fe8f9809200]: SSL 3.3 Handshake packet received. Epoch 0, length: 4 c: 5 REC[0x7fe8f9809200]: Expected Packet Handshake(22) c: 5 REC[0x7fe8f9809200]: Received Packet Handshake(22) with length: 4 c: 10 READ: Got 4 bytes from 0x5 c: 10 READ: read 4 bytes from 0x5 c: 10 RB: Have 5 bytes into buffer. Adding 4 bytes. c: 10 RB: Requested 9 bytes c: 5 REC[0x7fe8f9809200]: Decrypted Packet[4] Handshake(22) with length: 4 c: 4 HSK[0x7fe8f9809200]: SERVER HELLO DONE (14) was received. Length 0[0], frag offset 0, frag length: 1, sequence: 0 c: 4 HSK[0x7fe8f9809200]: CERTIFICATE was queued [950 bytes] c: 4 HSK[0x7fe8f9809200]: CLIENT KEY EXCHANGE was queued [70 bytes] c: 2 sign handshake cert vrfy: picked RSA-SHA256 with SHA256 c: 4 HSK[0x7fe8f9809200]: CERTIFICATE VERIFY was queued [312 bytes] c: 4 REC[0x7fe8f9809200]: Sent ChangeCipherSpec c: 9 INT: PREMASTER SECRET[32]: REDACTED c: 9 INT: CLIENT RANDOM[32]: REDACTED c: 9 INT: SERVER RANDOM[32]: REDACTED c: 9 INT: MASTER SECRET: REDACTED c: 5 REC[0x7fe8f9809200]: Initializing epoch #1 c: 9 INT: KEY BLOCK[72]: REDACTED c: 9 INT: CLIENT WRITE KEY [32]: REDACTED c: 9 INT: SERVER WRITE KEY [32]: REDACTED c: 9 INT: CLIENT WRITE IV [4]: REDACTED c: 9 INT: SERVER WRITE IV [4]: REDACTED c: 5 REC[0x7fe8f9809200]: Epoch #1 ready c: 4 HSK[0x7fe8f9809200]: Cipher Suite: ECDHE_RSA_AES_256_GCM_SHA384 c: 4 HSK[0x7fe8f9809200]: Initializing internal [write] cipher sessions c: 4 HSK[0x7fe8f9809200]: recording tls-unique CB (send) c: 4 HSK[0x7fe8f9809200]: FINISHED was queued [16 bytes] c: 5 REC[0x7fe8f9809200]: Preparing Packet Handshake(22) with length: 950 and min pad: 0 c: 9 ENC[0x7fe8f9809200]: cipher: NULL, MAC: MAC-NULL, Epoch: 0 c: 5 REC[0x7fe8f9809200]: Sent Packet[2] Handshake(22) in epoch 0 and length: 955 c: 5 REC[0x7fe8f9809200]: Preparing Packet Handshake(22) with length: 70 and min pad: 0 c: 9 ENC[0x7fe8f9809200]: cipher: NULL, MAC: MAC-NULL, Epoch: 0 c: 5 REC[0x7fe8f9809200]: Sent Packet[3] Handshake(22) in epoch 0 and length: 75 c: 5 REC[0x7fe8f9809200]: Preparing Packet Handshake(22) with length: 312 and min pad: 0 c: 9 ENC[0x7fe8f9809200]: cipher: NULL, MAC: MAC-NULL, Epoch: 0 c: 5 REC[0x7fe8f9809200]: Sent Packet[4] Handshake(22) in epoch 0 and length: 317 c: 5 REC[0x7fe8f9809200]: Preparing Packet ChangeCipherSpec(20) with length: 1 and min pad: 0 c: 9 ENC[0x7fe8f9809200]: cipher: NULL, MAC: MAC-NULL, Epoch: 0 c: 5 REC[0x7fe8f9809200]: Sent Packet[5] ChangeCipherSpec(20) in epoch 0 and length: 6 c: 5 REC[0x7fe8f9809200]: Preparing Packet Handshake(22) with length: 16 and min pad: 0 c: 9 ENC[0x7fe8f9809200]: cipher: AES-256-GCM, MAC: AEAD, Epoch: 1 c: 5 REC[0x7fe8f9809200]: Sent Packet[1] Handshake(22) in epoch 1 and length: 45 c: 10 READ: Got 5 bytes from 0x5 c: 10 READ: read 5 bytes from 0x5 c: 10 RB: Have 0 bytes into buffer. Adding 5 bytes. c: 10 RB: Requested 5 bytes c: 5 REC[0x7fe8f9809200]: SSL 3.3 ChangeCipherSpec packet received. Epoch 0, length: 1 c: 5 REC[0x7fe8f9809200]: Expected Packet ChangeCipherSpec(20) c: 5 REC[0x7fe8f9809200]: Received Packet ChangeCipherSpec(20) with length: 1 c: 10 READ: Got 1 bytes from 0x5 c: 10 READ: read 1 bytes from 0x5 c: 10 RB: Have 5 bytes into buffer. Adding 1 bytes. c: 10 RB: Requested 6 bytes c: 5 REC[0x7fe8f9809200]: Decrypted Packet[5] ChangeCipherSpec(20) with length: 1 c: 4 HSK[0x7fe8f9809200]: Cipher Suite: ECDHE_RSA_AES_256_GCM_SHA384 c: 3 ASSERT: buffers.c[get_last_packet]:1159 c: 10 READ: Got 5 bytes from 0x5 c: 10 READ: read 5 bytes from 0x5 c: 10 RB: Have 0 bytes into buffer. Adding 5 bytes. c: 10 RB: Requested 5 bytes c: 5 REC[0x7fe8f9809200]: SSL 3.3 Handshake packet received. Epoch 0, length: 40 c: 5 REC[0x7fe8f9809200]: Expected Packet Handshake(22) c: 5 REC[0x7fe8f9809200]: Received Packet Handshake(22) with length: 40 c: 10 READ: Got 40 bytes from 0x5 c: 10 READ: read 40 bytes from 0x5 c: 10 RB: Have 5 bytes into buffer. Adding 40 bytes. c: 10 RB: Requested 45 bytes c: 5 REC[0x7fe8f9809200]: Decrypted Packet[0] Handshake(22) with length: 16 c: 4 HSK[0x7fe8f9809200]: FINISHED (20) was received. Length 12[12], frag offset 0, frag length: 12, sequence: 0 c: 5 REC[0x7fe8f9809200]: Start of epoch cleanup c: 5 REC[0x7fe8f9809200]: Epoch #0 freed c: 5 REC[0x7fe8f9809200]: End of epoch cleanup c: INFO Handshake was completed: (TLS1.2)-(ECDHE-RSA-SECP256R1)-(AES-256-GCM) c: 5 REC[0x7fe8f9809200]: Preparing Packet Application Data(23) with length: 26989 and min pad: 0 c: 9 ENC[0x7fe8f9809200]: cipher: AES-256-GCM, MAC: AEAD, Epoch: 1 c: 5 REC[0x7fe8f9809200]: Sent Packet[2] Application Data(23) in epoch 1 and length: 16413 c: 5 REC[0x7fe8f9809200]: Preparing Packet Application Data(23) with length: 10605 and min pad: 0 c: 9 ENC[0x7fe8f9809200]: cipher: AES-256-GCM, MAC: AEAD, Epoch: 1 c: 5 REC[0x7fe8f9809200]: Sent Packet[3] Application Data(23) in epoch 1 and length: 10634 c: INFO Sending 'XXXXclient: task 2.5.1 key: REDACTED org: inthe_am protocol: v1 type: sync user: REDACTED ' REDACTED TASK JSON ' (26989 bytes) c: 10 READ: Got 0 bytes from 0x5 c: 10 READ: read 0 bytes from 0x5 c: 3 ASSERT: buffers.c[_gnutls_io_read_buffered]:591 c: 3 ASSERT: record.c[recv_headers]:1055 c: 3 ASSERT: record.c[_gnutls_recv_in_buffers]:1175 c: 3 ASSERT: record.c[_gnutls_recv_int]:1473 c: INFO expecting 0 bytes. c: 3 ASSERT: record.c[check_session_status]:1399 c: 5 REC[0x7fe8f9809200]: Start of epoch cleanup c: 5 REC[0x7fe8f9809200]: End of epoch cleanup c: 5 REC[0x7fe8f9809200]: Epoch #1 freed ```
adrienthebo commented 5 years ago

I ran into this issue a week or two ago and have seen failures more often than not, but when I went to record a failure with rr I got successes on two different laptops (Ubuntu and MacOS). This issue seems pretty transient, perhaps this is an issue with the inthe.am server getting overloaded?

For my successful syncs, I got these log messages as a response from the taskd instance:

Successful sync logs ``` c: INFO Sending 'XXXXclient: task 2.6.0 key: REDACTED org: inthe_am protocol: v1 type: sync user: REDACTED REDACTED ' (156 bytes) c: 10 READ: Got 5 bytes from 0x3 c: 10 READ: read 5 bytes from 0x3 c: 10 RB: Have 0 bytes into buffer. Adding 5 bytes. c: 10 RB: Requested 5 bytes c: 5 REC[0x55fb8ccfca40]: SSL 3.3 Application Data packet received. Epoch 1, length: 115 c: 5 REC[0x55fb8ccfca40]: Expected Packet Application Data(23) c: 5 REC[0x55fb8ccfca40]: Received Packet Application Data(23) with length: 115 c: 10 READ: Got 115 bytes from 0x3 c: 10 READ: read 115 bytes from 0x3 c: 10 RB: Have 5 bytes into buffer. Adding 115 bytes. c: 10 RB: Requested 120 bytes c: 5 REC[0x55fb8ccfca40]: Decrypted Packet[1] Application Data(23) with length: 91 c: INFO expecting 91 bytes. c: INFO Receiving 'XXXXclient: taskd 1.1.0 code: 201 status: No change ```

In the failure logs listed above we appear to have assertion failures, and without checking the source I'm guessing that we're getting zero length records. In this example we got a 5 byte read (though what's being read is beyond me at the moment), so it's something at this point that's failing.

I'll keep attempting to catch failures so I can debug this in the mean time.

adrienthebo commented 5 years ago

I was able to reproduce this issue and have both a wireshark capture and an rr capture. Unfortunately my wireshark fu is weak and I wasn't able to decrypt the session but there's enough information to approximate what's going on.

Session details

  1. The taskwarrior client and server successfully negotiate a TLS session.
    • task: c: INFO Handshake was completed: (TLS1.0)-(RSA)-(AES-256-CBC)-(SHA1)
  2. The taskwarrior client sends a sync command:
    • task: c: INFO Sending 'XXXXclient: task 2.5.1 [...]
    • gnutls: c: 5 REC[0x55b5d0e81e80]: Preparing Packet Application Data(23) with length: 156 and min pad: 0
    • gnutls: c: 5 REC[0x55b5d0e81e80]: Sent Packet[2] Application Data(23) in epoch 1 and length: 185
    • Wireshark reports an Application Data record has been sent with a payload of 180, which I'm guessing matches the gnutls packet +/- some headers.
  3. The taskd server responds with a TCP ACK for the previous packet.
  4. The taskd server sends a TCP FIN/ACK, which is not expected.
    • I would expect that the server would send a FIN before a FIN/ACK if anything, so this is non standard.
    • This early FIN/ACK is probably closing the SSL session early within gnutls, which is why we're seeing a read of 0 bytes.
  5. The task client sends a FIN/ACK, which is expected.
  6. The taskd server sends an ACK, which is expected.

Conclusions

  1. The task client and server are successfully negotiating a TLS session.
  2. The task client is (probably) sending a well formed TLS record, so we're not seeing overly long TLS records.
  3. The task server is sending a TCP FIN/ACK, which is very unusual. We should see either the client or the server send a FIN before a FIN/ACK, so this TCP stream is malformed.
  4. I did not observe that the client or server sent a TLS Alert record, so TLS isn't misbehaving.
  5. I was able to sync taskwarrior earlier today, and now it reliably fails.

This seems like the kind of issue that the taskwarrior devs might be familiar with; I don't know if I'll be able to carve off some time to chat with them though. This does seem very strange though.

djotaku commented 5 years ago

Just want to note I'm having the same issues. (About a week now) Intermittent although today I can't seem to get any syncs to work.

MartyLake commented 5 years ago

Sames issues, (about one hour now). task sync from command line gets "The specified session has been invalidated for some reason. Sync failed. Could not connect to the Taskserver.". sync from android taskwarrior have "ERROR: Malformed message Sync failed. Could not connect to the Taskserver". task rc.debug=1 rc.debug.tls=10 'rc.taskd.ciphers=NORMAL:%COMPAT' sync does not change anything.

MartyLake commented 5 years ago

I could successfully sync with android and terminal now.

adrienthebo commented 5 years ago

Today I was able to reliably sync taskwarrior up to 12:01 PDT, and at 12:07 taskwarrior started reliably failing. This has matched my observations that task sync works in the morning and fails later in the day. I've also observed a smattering of duplicated packets via Wireshark on the successful syncs. The fact that there's an instant transition from working to broken near noon is particularly intriguing; is it possible that someone's hammering the inthe.am server at around noonish and doesn't let up all day?

coddingtonbear commented 5 years ago

Sorry, folks, I was on vacation for a couple weeks and couldn't get to this until now, but now that I've had a look, it does look like we're encountering a problem that monitoring isn't currently looking out for. It appears that after the taskserver has been running for a while, it will begin failing to sync for certain users, and will fail for increasingly more users the longer the server is running until it is restarted either by the cron task monitoring it (which restarts the taskserver daily at 1100 UTC), or due to my monitoring script having failed to successfully synchronize (which checks every three minutes).

Here, you can find an stably anonymized sample of relevant log line entries (words in curly braces are anonymizations): https://gist.githubusercontent.com/coddingtonbear/9a11cf098e23d48c2e8438b7612dd377/raw/0ba834bef2e7fc517ead8bd18b724361080e3568/20190904110000.log -- the relevant lines to look for are:

Inthe.AM is almost certainly the highest-volume user of the taskserver anywhere, so it's very possible we're encountering a bug that only we will ever encounter, and I'm not totally sure what avenues to pursue for identifying what the underlying issue is. For the moment, I've just updated the crontab to automatically restart the taskserver hourly (instead of daily) to at least make it automatically recover at at least that interval, but I'll try to think of ways of updating the monitoring to identify this occurrence and restart when it has been identified.

coddingtonbear commented 5 years ago

I've updated inthe.am's fork of the taskserver such that it'll self-terminate should an "Unknown error" occur during synchronization: https://github.com/coddingtonbear/taskserver/commit/a8f234039174572de5efa63bae88b7c5d3f8ea74 . I think that'll work well as a workaround for now.