Skip to content

cursor.bulkcopy() fails,RuntimeError: Failed to connect to SQL Server: Protocol Error: Failed to receive token during login response parsing #600

Open
Open
cursor.bulkcopy() fails,RuntimeError: Failed to connect to SQL Server: Protocol Error: Failed to receive token during login response parsing#600
Assignees
bewithgaurav
Labels
area: bulk-copyIssues in cursor.bulkcopy()questionFurther information is requestedtriage doneIssues that are triaged by dev team and are in investigation.

Description

@minjun98
minjun98
opened on May 27, 2026

-- coding:utf-8 --

"""
Test script for cursor.bulkcopy() failure

This script isolates the bulkcopy() issue without GUI interference.
Result: bulkcopy() ALWAYS fails with:
"RuntimeError: Failed to connect to SQL Server: Protocol Error: Failed to receive token during login response parsing"
while the normal ODBC connection via mssql-python.connect() works perfectly fine.

Environment:

  • Python: 3.11.x
  • MSSQL-Python: 1.7.1 (latest pip version, includes PR FEAT: Pass all connection string params to mssql-py-core for bulk copy #439 which passes all connection string params to py-core)
  • MSSQL-Py-Core: bundled with mssql-python (Rust .pyd binary, cannot be upgraded separately from pip)
  • ODBC Driver: ODBC Driver 18 for SQL Server (auto-managed by mssql-python, no manual DSN setup needed)
  • SQL Server: Microsoft SQL Server 2016 (13.x)
  • Target table: temp_TEST_BATCHCOPY (56 columns, varchar/nvarchar only)
  • Auth: SQL Login (UID/PWD), with TrustServerCertificate=yes
  • OS: Windows 11
    """

import sys
import platform
import mssql_python

============================================================

0. Environment info

============================================================

print("=" * 60)
print("Environment")
print("=" * 60)
print(f"Python version: {sys.version}")
print(f"Platform: {platform.platform()}")
print(f"mssql-python version: {mssql_python.version}")

--- CONFIGURE THESE FOR YOUR ENVIRONMENT ---

CONN_STR = 'SERVER=192.168.0.18;DATABASE=AAB;UID=fa_app;PWD=qazwsx!@;TrustServerCertificate=yes;'
TABLE = 'temp_TEST_BATCHCOPY'

--------------------------------------------

try:
conn = mssql_python.connect(CONN_STR)
c = conn.cursor()
c.execute("SELECT @Version")
sql_ver = c.fetchone()[0]
print(f"SQL Server: {sql_ver.split(chr(10))[0].strip()}")
conn.close()
except Exception as e:
print(f"Cannot get SQL Server version (will continue): {e}")

============================================================

1. Normal connection + metadata query (always works)

============================================================

print()
print("=" * 60)
print("1. Normal connection + metadata query")
print("=" * 60)

conn = mssql_python.connect(CONN_STR)
c = conn.cursor()

c.execute("IF OBJECT_ID(N'temp_TEST_BATCHCOPY', N'U') IS NULL SELECT 0 ELSE SELECT 1")
exists = c.fetchone()[0]
print(f"Table exists: {exists}")

c.execute("""SELECT COLUMN_NAME FROM INFORMATION_SCHEMA.COLUMNS
WHERE TABLE_NAME = ? ORDER BY ORDINAL_POSITION""", (TABLE,))
table_columns = [r[0] for r in c.fetchall()]
print(f"Number of columns: {len(table_columns)}")
print(f"Column names (first 5): {table_columns[:5]}...")

conn.close()

============================================================

2. Test cursor.bulkcopy()

============================================================

print()
print("=" * 60)
print("2. Test cursor.bulkcopy()")
print("=" * 60)

Build 5 rows of test data matching the table column count

test_data = [tuple(f"test_row{i}_col{j}" for j in range(len(table_columns))) for i in range(5)]
print(f"Test data rows: {len(test_data)}")
print(f"Values per row: {len(test_data[0])}")

fresh_conn = mssql_python.connect(CONN_STR)
fresh_c = fresh_conn.cursor()

try:
result = fresh_c.bulkcopy(
TABLE,
test_data,
batch_size=0,
timeout=30,
column_mappings=table_columns,
)
print(f"bulkcopy() SUCCEEDED: {result}")
except Exception as e:
print(f"bulkcopy() FAILED!")
print(f" Exception type: {type(e).name}")
print(f" Error message: {str(e)}")
finally:
fresh_conn.close()

============================================================

3. Verify if any data was actually inserted

============================================================

print()
print("=" * 60)
print("3. Verify row count after test")
print("=" * 60)

try:
vc = mssql_python.connect(CONN_STR)
cr = vc.cursor()
cr.execute(f"SELECT COUNT(*) FROM [{TABLE}]")
print(f"Table '{TABLE}' row count: {cr.fetchone()[0]}")
vc.close()
except Exception as e:
print(f"Verification failed (may be fine): {e}")

============================================================

4. Connection string variant matrix

============================================================

print()
print("=" * 60)
print("4. Connection string variant matrix")
print("=" * 60)

BASE = 'SERVER=192.168.0.18;DATABASE=AAB;UID=fa_app;PWD=qazwsx!@'
data2 = [tuple(f"v{i}_c{j}" for j in range(len(table_columns))) for i in range(2)]

variants = [
(f'{BASE};TrustServerCertificate=yes;', 'TrustServerCertificate=yes'),
(f'{BASE};Encrypt=yes;TrustServerCertificate=yes;','Encrypt=yes;TrustSC=yes'),
(f'{BASE};Encrypt=no;TrustServerCertificate=yes;', 'Encrypt=no;TrustSC=yes'),
(f'{BASE};Encrypt=no;', 'Encrypt=no (no Trust)'),
(f'{BASE};encrypt=no;TrustServerCertificate=yes;', 'lowercase encrypt=no'),
]

for cs, label in variants:
odbc_ok = False
try:
t = mssql_python.connect(cs)
t.close()
odbc_ok = True
except Exception:
pass

try:
    b = mssql_python.connect(cs)
    bc = b.cursor()
    bc.bulkcopy(TABLE, data2, batch_size=0, timeout=30, column_mappings=table_columns)
    b.close()
    print(f"[{label:35s}] ODBC={'OK ' if odbc_ok else 'ERR'} | BULKCOPY=OK")
except Exception as e:
    err = str(e).replace('\n', ' ')[:80]
    print(f"[{label:35s}] ODBC={'OK ' if odbc_ok else 'ERR'} | BULKCOPY=FAIL: {err}")

Activity

  1. github-actions commented on May 27, 2026

    @github-actions
    github-actionsbot
    on May 27, 2026 – with GitHub Actions

    Hi minjun98, thank you for opening this issue!

    Our team will review it shortly. We aim to triage all new issues within 24-48 hours and get back to you.

    If you have additional information to share, please feel free to update the issue.

    Thank you for your patience!

  2. github-actions
    added
    triage neededFor new issues, not triaged yet.
    on May 27, 2026

  3. subrata-ms commented on May 27, 2026

    @subrata-ms
    Subrata (subrata-ms)
    on May 27, 2026
    Contributor

    This seems to be a bug and below is my high-level analysis. We are currently looking into this issue.

    cursor.bulkcopy() appears to fail in its own native/py-core connection path rather than in the main mssql_python.connect() path. Internal bulkcopy design docs explicitly state that Cursor.bulkcopy(...) opens a Rust/native connection using the connection string and closes it after the operation, and public issue history already documents prior cases where normal connect() succeeded while bulkcopy() failed because it created a separate internal PyCoreConnection. Given the current repro fails with Protocol Error: Failed to receive token during login response parsing while normal SQL-auth connection succeeds in the same process, the most likely issue is in the py-core login-handshake / login-response parsing path used only by bulkcopy, potentially with SQL Server 2016 compatibility. The SQL Server 2016-specific compatibility point is a working hypothesis; the confirmed evidence is the separate bulkcopy connection path and prior bulkcopy-only connection regressions.

  4. Subrata (subrata-ms)
    added
    bugSomething isn't working
    regressionTracks issues which are regressions
    on May 27, 2026
  5. Subrata (subrata-ms)
    assigned
    Subrata (subrata-ms)
    and
    Gaurav Sharma (bewithgaurav)
    and unassigned
    Subrata (subrata-ms)
    on May 29, 2026
  6. Gaurav Sharma (bewithgaurav)
    added
    triage doneIssues that are triaged by dev team and are in investigation.
    and removed
    triage neededFor new issues, not triaged yet.
    on Jun 2, 2026
  7. Gaurav Sharma (bewithgaurav)
    added a commit that references this issue on Jun 2, 2026

    CHORE: Strip pr-validation to SQL 2016 bulkcopy repro for #600

    e56ede9

  8. bewithgaurav commented on Jun 2, 2026

    @bewithgaurav
    Gaurav Sharma (bewithgaurav)
    on Jun 2, 2026
    Collaborator

    Thanks for raising this issue & detailed scripts minjun98

    Attempted to reproduce this against SQL Server 2016 SP1 (13.0.4001.0) on Windows x64 using the same connection string variants from the repro script (Encrypt=yes/no, TrustServerCertificate=yes/no, 56-column wide table). All bulkcopy operations succeeded - both with mssql-python 1.7.1 and 1.8.0.

    CI run: https://sqlclientdrivers.visualstudio.com/public/_build/results?buildId=154699&view=results

    What we tested:

    • Normal ODBC connection (baseline) ✅
    • Bulkcopy with baseline connection string ✅
    • Bulkcopy with all 4 connection string variants from your script ✅
    • Bulkcopy with 56 NVARCHAR(100) columns ✅

    Since we couldn't reproduce the failure, we need your help narrowing this down.

    Could you try the following?

    1. Upgrade to 1.8.0 (pip install --upgrade mssql-python) and check if the issue persists.

    2. If it still fails, run your repro script with Rust TDS tracing enabled. This will capture the exact bytes exchanged during the login handshake and show us what token/byte causes the parse failure:

      set MSSQL_TDS_TRACE=true
set MSSQL_TDS_TRACE_LEVEL=debug
python your_repro_script.py

      This creates a log file under ./mssql_python_logs/. Please attach it here.

    3. What is your exact SQL Server version? (Run SELECT @@VERSION and paste the full output - we need the SP/CU level, not just "2016 13.x")

    This will help us determine whether the issue is specific to your SQL Server patch level, network configuration, or something else in the environment.

  9. Gaurav Sharma (bewithgaurav)
    added
    questionFurther information is requested
    area: bulk-copyIssues in cursor.bulkcopy()
    and removed
    bugSomething isn't working
    regressionTracks issues which are regressions
    on Jun 2, 2026

  10. bewithgaurav commented on Jun 10, 2026

    @bewithgaurav
    Gaurav Sharma (bewithgaurav)
    on Jun 10, 2026
    Collaborator

    minjun98 - hi, bumping this up again
    let us know if the upgrade helped, if not please help us with the logs as mentioned above

  11. camiloatencio95 commented on Jun 23, 2026

    @camiloatencio95
    camiloatencio95
    on Jun 23, 2026

    I ran into this issue when trying to connect to a db that was configured with AlwaysOn. The short term solution was to establish the connection to the "master" database always and perform bulkcopy operations using fully qualified table names with this approach no issues whatsoever. Gaurav Sharma (@bewithgaurav) maybe its worth trying to reproduce on an alwayson setup.

  12. saurabh500 commented on Jun 23, 2026

    @saurabh500
    Saurabh Singh (saurabh500)
    on Jun 23, 2026
    Contributor

    camiloatencio95 is it possible for you to provide the traces with the env vars that Gaurav Sharma (@bewithgaurav) has provided?

  13. camiloatencio95 commented on Jun 25, 2026

    @camiloatencio95
    camiloatencio95
    on Jun 25, 2026

    hi Gaurav Sharma (@bewithgaurav) Saurabh Singh (@saurabh500) ! I did and this is what I get... I did obfuscate some things. but i think the error cause is shown there. I am able to use the driver by stablishing connection to master and then using fully qualified object names. Not ideal but it works.

    `2026-06-25T18:53:04.067Z, 2, INFO, mssql_py_core::connection, Creating new PyCoreConnection
    2026-06-25T18:53:04.069Z, 2, DEBUG, mssql_py_core::connection, Converting Python dict to ClientContext
    2026-06-25T18:53:04.069Z, 2, DEBUG, mssql_py_core::connection, Extracting connection parameters from Python dict
    2026-06-25T18:53:04.069Z, 2, DEBUG, mssql_py_core::connection, Server: dbserver.domain.com,1433
    2026-06-25T18:53:04.069Z, 2, DEBUG, mssql_py_core::connection, Creating ClientContext - database: Some("target_db"), app: mssql-python, timeout: 15s, packet_size: 4096, encryption: Required
    2026-06-25T18:53:04.069Z, 2, INFO, mssql_py_core::connection, Encryption options: mode=Required, trust_server_certificate=true, host_name_in_cert=None, server_certificate=None
    2026-06-25T18:53:04.069Z, 2, INFO, mssql_py_core::connection, Attempting connection to datasource: dbserver.domain.com,1433
    2026-06-25T18:53:04.069Z, 2, DEBUG, mssql_tds::connection_provider::tds_connection_provider, Connection strategy:
    Connection strategy for 'dbserver.domain.com'
    Server: dbserver.domain.com
    Explicit protocol: true

    Action sequence:

    1. Connect via TCP to dbserver.domain.com:1433

    2026-06-25T18:53:04.069Z, 2, DEBUG, mssql_tds::connection_provider::tds_connection_provider, Resolved 1 transport context(s) from action chain
    2026-06-25T18:53:04.069Z, 2, DEBUG, mssql_tds::connection_provider::tds_connection_provider, Attempt 0: connecting with Tcp { host: "dbserver.domain.com", port: 1433, instance_name: None }
    2026-06-25T18:53:04.069Z, 2, INFO, mssql_tds::connection::transport::network_transport, Connecting to TCP transport (sequential): dbserver.domain.com:1433
    2026-06-25T18:53:04.070Z, 2, INFO, mssql_tds::connection::transport::network_transport, Socket addresses: IntoIter([10.208.114.220:1433])
    2026-06-25T18:53:04.086Z, 2, INFO, mssql_tds::connection::transport::network_transport, Connected to TCP transport: dbserver.domain.com:1433
    2026-06-25T18:53:04.086Z, 2, INFO, mssql_tds::connection::transport::network_transport, Creating NetworkTransport for TDS 7.4 with TLS wrapping
    2026-06-25T18:53:04.086Z, 2, DEBUG, mssql_tds::io::packet_writer, Sending packet of size: 105
    2026-06-25T18:53:04.086Z, 2, DEBUG, mssql_tds::io::packet_writer, Packet content: Length: 105 (0x69) bytes

    2026-06-25T18:53:04.104Z, 2, DEBUG, mssql_tds::connection::transport::network_transport, Received packet of size: 54
    2026-06-25T18:53:04.104Z, 2, DEBUG, mssql_tds::connection::transport::network_transport, Packet content: Length: 54 (0x36) bytes

    2026-06-25T18:53:04.104Z, 2, INFO, mssql_tds::connection::transport::ssl_handler, TLS config: encryption_mode=Required, trust_server_certificate=true, server_certificate=None, host_name_in_cert=None, resolved_host_name=dbserver.domain.com, server_host_name=dbserver.domain.com
    2026-06-25T18:53:04.104Z, 2, INFO, mssql_tds::connection::transport::ssl_handler, Starting TLS handshake to dbserver.domain.com using host dbserver.domain.com
    2026-06-25T18:53:04.106Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, poll_write() called.
    2026-06-25T18:53:04.106Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, poll_write() calling poll_write_vectored() internally
    2026-06-25T18:53:04.106Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, poll_write_vectored() called
    2026-06-25T18:53:04.106Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, Flattening 2 slices into single buffer of 284 bytes for atomic write
    2026-06-25T18:53:04.106Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, Bytes written 284
    2026-06-25T18:53:04.106Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, Write data preview (first 16 bytes): [12, 01, 01, 1C, 00, 00, 01, 00]
    2026-06-25T18:53:04.106Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, poll_flush() called.
    2026-06-25T18:53:04.127Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, Read bytes read 8
    2026-06-25T18:53:04.127Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, Header fully read
    2026-06-25T18:53:04.127Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, Payload bytes read: 1024
    2026-06-25T18:53:04.128Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, Payload bytes read: 601
    2026-06-25T18:53:04.134Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, poll_write() called.
    2026-06-25T18:53:04.134Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, poll_write() calling poll_write_vectored() internally
    2026-06-25T18:53:04.134Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, poll_write_vectored() called
    2026-06-25T18:53:04.134Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, Flattening 2 slices into single buffer of 166 bytes for atomic write
    2026-06-25T18:53:04.134Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, Bytes written 166
    2026-06-25T18:53:04.134Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, Write data preview (first 16 bytes): [12, 01, 00, A6, 00, 00, 02, 00]
    2026-06-25T18:53:04.134Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, poll_flush() called.
    2026-06-25T18:53:04.153Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, Read bytes read 8
    2026-06-25T18:53:04.153Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, Header fully read
    2026-06-25T18:53:04.153Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, Payload bytes read: 51
    2026-06-25T18:53:04.219Z, 2, INFO, mssql_tds::message::login, Login Server name: dbserver.domain.com,1433
    2026-06-25T18:53:04.219Z, 2, DEBUG, mssql_tds::message::login, self.content_next_offset=316
    2026-06-25T18:53:04.219Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, poll_write() called.
    2026-06-25T18:53:04.219Z, 2, DEBUG, mssql_tds::io::packet_writer, Sending packet of size: 544
    2026-06-25T18:53:04.219Z, 2, DEBUG, mssql_tds::io::packet_writer, Packet content: Length: 544 (0x220) bytes

    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::connection::transport::network_transport, Received packet of size: 494
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::connection::transport::network_transport, Packet content: Length: 494 (0x1ee) bytes

    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::io::token_stream, Received token type: EnvChange (227)
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::io::token_stream, Parsing token type: EnvChange
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::token::parsers::envchange_parser, Parsing EnvChange token with type and subtype Database
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::message::login, Received token: EnvChange during login response parsing
    2026-06-25T18:53:04.239Z, 2, INFO, mssql_tds::message::login, Received EnvChange during login response parsing.
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::message::login, Capturing change property: String: EnvChangeTokenValuePairs { old_value: "master", new_value: "target_db" } with sub type: Database
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::io::token_stream, Received token type: Info (171)
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::io::token_stream, Parsing token type: Info
    2026-06-25T18:53:04.239Z, 2, INFO, mssql_tds::token::parsers::info_parser, Info message: Some("Changed database context to 'target_db'.")
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::message::login, Received token: Info during login response parsing
    2026-06-25T18:53:04.239Z, 2, INFO, mssql_tds::message::login, Received Info during login response parsing.
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::io::token_stream, Received token type: EnvChange (227)
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::io::token_stream, Parsing token type: EnvChange
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::token::parsers::envchange_parser, Parsing EnvChange token with type and subtype SqlCollation
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::message::login, Received token: EnvChange during login response parsing
    2026-06-25T18:53:04.239Z, 2, INFO, mssql_tds::message::login, Received EnvChange during login response parsing.
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::message::login, Capturing change property: SqlCollation: EnvChangeTokenValuePairs { old_value: None, new_value: Some(INFO: 12583945 LCID: 1033, ComparisonStyle: 12, SortID: 51, IsUtf8: false, IgnoreCase: false) } with sub type: SqlCollation
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::io::token_stream, Received token type: EnvChange (227)
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::io::token_stream, Parsing token type: EnvChange
    2026-06-25T18:53:04.239Z, 2, DEBUG, mssql_tds::token::parsers::envchange_parser, Parsing EnvChange token with type and subtype DatabaseMirroringPartner
    2026-06-25T18:53:04.239Z, 2, ERROR, mssql_tds::message::login, Failed to receive token during login response parsing. Error: UnimplementedFeature { feature: "DatabaseMirroringPartner", context: "EnvChange token parsing not yet implemented" }
    2026-06-25T18:53:04.240Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, poll_write() called.
    2026-06-25T18:53:04.240Z, 2, DEBUG, mssql_tds::connection::transport::ssl_handler, poll_flush() called.
    2026-06-25T18:53:04.240Z, 2, DEBUG, mssql_tds::connection_provider::tds_connection_provider, Connection attempt failed: Protocol Error: Failed to receive token during login response parsing.
    2026-06-25T18:53:04.240Z, 2, ERROR, mssql_py_core::connection, Failed to connect to SQL Server: Protocol Error: Failed to receive token during login response parsing.
    `

  14. saurabh500 commented on Jun 25, 2026

    @saurabh500
    Saurabh Singh (saurabh500)
    on Jun 25, 2026
    Contributor

    cc David Engel (@David-Engel)

  15. saurabh500 commented on Jun 25, 2026

    @saurabh500
    Saurabh Singh (saurabh500)
    on Jun 25, 2026
    Contributor

    camiloatencio95 This trace has the information we need. Thanks. I think we know what to do next.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

area: bulk-copyIssues in cursor.bulkcopy()questionFurther information is requestedtriage doneIssues that are triaged by dev team and are in investigation.

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions